Four step clocks in our job runner, and the one over a model call was shorter than the model client's own retry

Munchable has a lot of pages that nobody wrote. The answers index and the few hundred pages under it, like is soy sauce gluten free, are generated at build time from data the product holds. Which means the interesting question is not how the pages render. It is what fills the data, and that is background work: long passes over catalogue vocabulary, batched out to a model, written back.

This post is about the runner underneath that work, and specifically about a timeout constant that was set to a sensible-looking number and silently broke every long run we tried.

What is left of our background infrastructure

Here is the whole of apps/web/vercel.json:

{
  "$schema": "https://openapi.vercel.sh/vercel.json",
  "crons": [
    { "path": "/api/cron/rewards-settle", "schedule": "0 4 8 * *" },
    { "path": "/api/cron/indexnow",       "schedule": "0 * * * *" }
  ]
}

Two scheduled jobs. One settles contributor rewards, monthly. One announces changed URLs to IndexNow, hourly, and almost every run submits nothing and costs a single Redis read. Neither of them is the curation work this post is about.

There used to be more. A hosted background-task platform ran the long passes, and a set of scheduled jobs drained the backlog behind it. Both are gone, and the comment in the file that replaced them says why better than I can paraphrase:

// There used to be a second runner here. [...] Both are gone: the scan path
// now names what it can inline and writes the answer straight into the
// overlay, so the only work left after a response is the tail of one label,
// which is one overlay read and at most one model call. That fits in
// `after()`, and a runner that exists to carry it is a bill and a second
// deployment target for nothing.

The deletion was only possible because of a change on the request path: once the live path resolved what it could inline, the thing a queue was carrying stopped being a workload and became a tail. Next's after() carries a tail. The whole file is now 39 lines, most of it comment, wrapping one function that never throws:

export function dispatchResolveLabel(payload: ResolveLabelPayload): void {
  if (payload.words.length === 0) return;
  try {
    after(async () => {
      try {
        await resolveLabelWords(payload);
      } catch (e) {
        console.warn(`[dispatch] resolve-label failed: ${String(e).slice(0, 200)}`);
      }
    });
  } catch {
    // Outside a request scope (tests, scripts): nothing to schedule on.
  }
}

Best effort by design: a failure here loses no data, because the words are in the backlog either way and the bulk pass will finish them.

The bulk pass itself is now a command:

pnpm job taxonomy-curate --until-done --concurrency 4

Three job names, one CLI, no clock, run by a person who is watching. That last part is a feature. A bulk pass over a whole catalogue is the kind of job where you want to read the log as it goes, not discover the outcome in a dashboard tomorrow.

A run that is one awaited function has exactly one error message

The nightly curation job, back when it was nightly, stalled five nights in a row after its first commit. Nothing in the logs said where. The entire run was one awaited function, and the platform's five-minute kill was its only timeout, so the whole report was FUNCTION_INVOCATION_TIMEOUT and the only debugging move available was to guess.

So the jobs got a JobRun with a named step:

async step<T>(name: string, fn: () => Promise<T>, opts: { timeoutMs?: number } = {}): Promise<T> {
  const t0 = Date.now();
  try {
    const result = await withTimeout(fn(), opts.timeoutMs ?? DB_STEP_MS, name);
    this.log.info(`step=${name} ms=${Date.now() - t0}`);
    return result;
  } catch (e) {
    this.log.warn(`step=${name} ms=${Date.now() - t0} failed: ${String(e).slice(0, 300)}`);
    throw e;
  }
}

It logs the name and duration on success, logs and rethrows on failure, and rejects on its own after timeoutMs with a StepTimeout that carries the step name. A stall now reads step "load-overlay" timed out after 30000 ms instead of a platform error code.

withTimeout lives in one file for the whole app, and that consolidation has its own small story: there were three copies of it, in the job runner, the OCR route and the taxonomy cache, identical except for the error each one rejected with. Three shapes meant nothing that keyed on "timed out" could see all three.

The four clocks, and the one that was wrong

Every step now takes a budget from one of four constants:

export const DB_STEP_MS = 30_000;          // a database round trip
export const MODEL_STEP_MS = 120_000;      // one structured-output model call
export const MODEL_BATCH_STEP_MS = 210_000; // one batch inside a curation job
export const MINING_STEP_MS = 280_000;     // a whole-catalogue aggregate

Look at the second and third. A single model call gets 120 seconds. One batch, which is a model call plus the validation and writes that follow it, gets 210. That ordering is not slack for the write, and the reason it is not is the bug.

The curation job builds its client like this:

createOpenAIClient({ timeoutMs: 90_000, maxRetries: 1 })

90 second timeout, one retry. A call that times out and is legitimately retried therefore runs for up to 180 seconds and then succeeds. With the step clock at 120, that successful call was reported as a stalled step. Three failed batches in a row end a run, which is the policy I will come back to, so three healthy retries in a row ended it too.

That is how a 36,000 row drain stopped after 320 rows, with a log full of timeouts and nothing actually broken.

The generalisation is the only part of this worth keeping: a timeout wrapped around a call that has its own retry policy must clear that policy's worst case, or it is not measuring the call, it is measuring your patience. 90 times two is 180, and 210 is the first round number above it.

Concurrency made this likelier without causing it. The job puts several model calls on the wire at once; the provider queues them; every call in flight gets slower as the others pile up; the ones that then retry are exactly the ones that used to trip a 120 second clock. The bug was always there and concurrency is what found it.

The timeout does not stop anything

Worth being blunt about, because the name suggests otherwise. withTimeout races a promise against a setTimeout. It does not cancel the underlying work. A Postgres query that trips a 30 second step clock keeps running until the statement finishes or the server's own statement timeout kills it.

That is deliberate, and it is also a compromise I would not defend in every codebase. What the step clock buys here is visibility: the run reports which step hung and moves on to its failure policy instead of sitting there until the platform kills the invocation. What it does not buy is resource reclamation. In a job runner where the next run re-reads the same open rows anyway, visibility was the thing worth having, and real cancellation would have meant threading an AbortSignal through every call site for a benefit the operator does not feel.

Three failures in a row, and the calls we abandon

The other policy in the runner is how a run gives up:

export const MAX_CONSECUTIVE_FAILURES = 3;

One failed batch is a blip and the next batch is tried. Three in a row is an outage or an exhausted API budget, and every further batch burns the deadline to fail the same way. When the third one lands, the run stops, and the calls already on the wire are discarded without being awaited.

Abandoning in-flight work is only acceptable because of one property: the rows a batch was asked about stay open until a write closes them. A dropped call costs the money already spent on it and nothing else, because the next run asks about those rows again. Every retry and give-up decision in this runner leans on that, and if the writes were not idempotent none of the policy above would be cheap enough to be this blunt.

There is a second, quieter lesson in the same function. The failure policy used to be copied into each job, and the copies disagreed: one counted a failed write as a failed batch and the other did not. It now lives in one place where throwing from the per-batch handler counts the same way a model error does, so a job cannot lose track of half of its own policy. The same applied to loading state at the top of each job: five copied lines, five places to edit, and the fifth was always the one that got missed.

What I am still unhappy with

• Four magic numbers in a constants block. They are commented, and each comment explains what the number has to clear, but nothing tests that MODEL_BATCH_STEP_MS still exceeds the client's worst case. If somebody raises maxRetries to 2, the 320-row bug comes back and the only warning is a comment.
• --concurrency is a flag with no guard rail. Set it high enough and you discover the provider's queueing behaviour the same way we did.
• The CLI is the runner. That is right for a bulk pass with one operator, and it will be wrong the first time the work has to happen without somebody present.

See the output

The thing the jobs are for is reading a label and saying something useful about it. The web side of that is public, so you can check the data without installing anything: the answers index, the conditions the app covers, and the hidden gluten reference list, which is the densest page on the site and the one most obviously downstream of a long backlog drain.

If you want the page-generation half of this, I wrote about it separately: our answer pages contain no written answers.