How to test job timeout and cancellation

Give the worker a deadline, then watch what the handler does after it expires. Under a 1000 ms deadline the queue printed gave up on job 1 at 1037 ms and the same handler printed returned "charged" at 3078 ms. The queue stopped waiting. The work did not stop.

Why check this

A timeout is a decision on the queue side. Cancellation is something the handler has to do. Nothing joins the two unless the handler reads its cancellation signal and stops on it.

Run this before a release that changes a long-running handler, on staging sign-off, and after anyone shortens an attempt timeout. It prevents this: a settlement job passes its budget, the queue hands the row to a second worker, and the customer is charged twice by two copies of a job the dashboard calls failed.

The target below is a queue in SQLite. Two handlers do identical 3 s work under a 1000 ms deadline, and only one of them reads its signal.

Prerequisites

Node 22. The queue uses node:sqlite and prints an ExperimentalWarning on every start. Steps 1, 2 and 4 keep those two lines. The blocks marked truncated cut them.
Timers, signals and their semantics: AbortSignal.timeout and timers/promises.
Port 8931 free on 127.0.0.1, confirmed with netstat -ano | grep 8931.
The target, saved as queue.mjs: queue, worker and downstream service in one file. coop passes the signal to every sleep and to fetch, deaf passes it nowhere. A charge that reaches effects.log cannot be taken back.

import { DatabaseSync } from 'node:sqlite';
import { createServer } from 'node:http';
import { appendFileSync } from 'node:fs';
import { setTimeout as sleep } from 'node:timers/promises';
import { fork } from 'node:child_process';

const PORT = 8931;
const BASE = `http://127.0.0.1:${PORT}`;
const [mode = 'serve', h = 'deaf', workers = '1', deadline = '1000', cancelAt = '0'] = process.argv.slice(2);
const t0 = Date.now();
const log = (...x) => console.log(String(Date.now() - t0).padStart(5), ...x);
const iso = () => new Date().toISOString().replace('T', ' ').slice(0, 19);

const db = new DatabaseSync('jobs.db');
db.exec('PRAGMA journal_mode = WAL');
db.exec('PRAGMA busy_timeout = 2000');
db.exec(`CREATE TABLE IF NOT EXISTS job (id INTEGER PRIMARY KEY, name TEXT, status TEXT,
  attempts INTEGER DEFAULT 0, worker TEXT, claimed_at TEXT, finished_at TEXT, note TEXT, cancel INTEGER DEFAULT 0)`);

// The work: six chunks, then one downstream call that has a side effect.
// coop passes the signal into every await. deaf passes it nowhere.
const handlers = {
  coop: async (job, signal, worker) => {
    for (let i = 1; i <= 6; i += 1) { await sleep(500, undefined, { signal }); log(`   ${worker} job ${job.id} chunk ${i}/6`); }
    await fetch(`${BASE}/charge/${job.id}`, { method: 'POST', signal });
    return 'charged';
  },
  deaf: async (job, signal, worker) => {
    for (let i = 1; i <= 6; i += 1) { await sleep(500); log(`   ${worker} job ${job.id} chunk ${i}/6`); }
    await fetch(`${BASE}/charge/${job.id}`, { method: 'POST' });
    return 'charged';
  },
};

function claim(worker, id) {
  const row = db.prepare("SELECT * FROM job WHERE status = 'queued' AND id = ?").get(id);
  if (!row) return null;
  db.prepare("UPDATE job SET status='running', attempts=attempts+1, worker=?, claimed_at=? WHERE id=?")
    .run(worker, iso(), row.id);
  return { ...row, attempts: row.attempts + 1 };
}

async function attempt(worker, handler, deadlineMs, id) {
  const job = claim(worker, id);
  if (!job) { log(`${worker} found nothing to claim`); return { watched: Promise.resolve() }; }
  log(`${worker} claimed job ${job.id}, attempt ${job.attempts}, deadline ${deadlineMs} ms`);
  const ctl = new AbortController();
  const poll = setInterval(() => {
    if (db.prepare('SELECT cancel FROM job WHERE id=?').get(job.id).cancel) ctl.abort(new Error('cancel requested'));
  }, 200);
  const signal = AbortSignal.any([AbortSignal.timeout(deadlineMs), ctl.signal]);
  const work = handlers[handler](job, signal, worker);
  const watched = work.then((r) => log(`${worker} handler for job ${job.id} returned "${r}"`),
    (e) => log(`${worker} handler for job ${job.id} stopped: ${e.name}`));
  const stopped = new Promise((_, rej) => signal.addEventListener('abort', () => rej(signal.reason), { once: true }));
  try {
    const r = await Promise.race([work, stopped]);
    db.prepare("UPDATE job SET status='done', finished_at=?, note=? WHERE id=?").run(iso(), r, job.id);
    log(`${worker} job ${job.id} done`);
  } catch (e) {
    const why = e?.name === 'TimeoutError' ? `attempt exceeded ${deadlineMs} ms` : 'cancel requested';
    db.prepare("UPDATE job SET status='queued', worker=NULL, claimed_at=NULL, note=? WHERE id=?").run(why, job.id);
    log(`${worker} gave up on job ${job.id}: ${why}. Row is queued again.`);
  } finally { clearInterval(poll); }
  return { watched };   // the handler promise, still pending when the queue gave up
}

const enqueue = () => Number(db.prepare("INSERT INTO job (name, status) VALUES ('settle-payments','queued')").run().lastInsertRowid);

if (mode === 'serve') {
  createServer((req, res) => {
    const [, head, arg] = req.url.split('/');
    if (head === 'charge') {
      appendFileSync('effects.log', `${iso()} charged job ${arg}\n`);
      res.end('charged\n');
    } else if (head === 'cancel') {
      db.prepare('UPDATE job SET cancel=1 WHERE id=?').run(Number(arg));
      res.end(`cancel requested for job ${arg}\n`);
    } else if (head === 'jobs') {
      res.writeHead(200, { 'content-type': 'application/json' });
      res.end(JSON.stringify(db.prepare('SELECT id,status,attempts,worker,finished_at,note FROM job').all()) + '\n');
    } else { res.writeHead(404); res.end(); }
  }).listen(PORT, '127.0.0.1', () => console.log(`queue service on ${PORT}, pid ${process.pid}`));
} else if (mode === 'run') {
  const id = enqueue();
  log(`enqueued job ${id}: handler ${h}, ${workers} worker(s), deadline ${deadline} ms`);
  if (Number(cancelAt) > 0) setTimeout(() => fetch(`${BASE}/cancel/${id}`, { method: 'POST' }).then(() => log(`operator posted /cancel/${id}`)), Number(cancelAt));
  const pending = [(await attempt('w1', h, Number(deadline), id)).watched];
  if (workers === '2') pending.push((await attempt('w2', h, Number(deadline), id)).watched);
  await Promise.allSettled(pending);
  log('every handler has settled');
} else if (mode === 'kill') {
  const id = enqueue();
  log(`enqueued job ${id}, forking a worker`);
  const child = fork(process.argv[1], ['child', 'deaf', '1', '60000', String(id)]);
  child.on('exit', (code, sig) => {
    log(`child exited code=${code} signal=${sig}`);
    log(JSON.stringify(db.prepare('SELECT id,status,attempts,worker,claimed_at,finished_at FROM job WHERE id=?').get(id)));
  });
  setTimeout(() => { log('parent sends SIGTERM to the worker'); child.kill('SIGTERM'); }, 1200);
} else if (mode === 'child') {
  process.on('SIGTERM', () => {
    log('child: SIGTERM handler ran, releasing the row');
    db.exec("UPDATE job SET status='queued', worker=NULL, note='worker stopped' WHERE status='running'");
    process.exit(0);
  });
  await attempt('w-child', 'deaf', Number(deadline), Number(cancelAt));
}

Steps

Start the queue service and keep the pid it prints.

node queue.mjs serve

(node:42552) ExperimentalWarning: SQLite is an experimental feature and might change at any time
(Use `node --trace-warnings ...` to show where the warning was created)
queue service on 8931, pid 42552

It holds the job table, the cancel endpoint and the charge log. Step 10 stops it by pid.

Run a job whose handler never reads its signal, deadline 1000 ms.

node queue.mjs run deaf 1 1000

   17 enqueued job 1: handler deaf, 1 worker(s), deadline 1000 ms
 20 w1 claimed job 1, attempt 1, deadline 1000 ms
(node:37080) ExperimentalWarning: SQLite is an experimental feature and might change at any time
(Use `node --trace-warnings ...` to show where the warning was created)
529    w1 job 1 chunk 1/6
1037 w1 gave up on job 1: attempt exceeded 1000 ms. Row is queued again.
1037    w1 job 1 chunk 2/6
1542    w1 job 1 chunk 3/6
2045    w1 job 1 chunk 4/6
2546    w1 job 1 chunk 5/6
3059    w1 job 1 chunk 6/6
3078 w1 handler for job 1 returned "charged"
3079 every handler has settled

The first column is milliseconds. Chunk 2 of 6 is logged at 1037 ms, one line under the queue giving up, and the charge lands 2 s later.

3
Step 3.
Ask the queue what it believes about that job.
```
curl -s http://127.0.0.1:8931/jobs
```
```
[{"id":1,"status":"queued","attempts":1,"worker":null,"finished_at":null,"note":"attempt exceeded 1000 ms"}]
```
No worker, no finish time, one attempt spent. Every field is about the queue, none about the handler.

Run the same work with the signal passed into every await.

node queue.mjs run coop 1 1000

    2 enqueued job 2: handler coop, 1 worker(s), deadline 1000 ms
  4 w1 claimed job 2, attempt 1, deadline 1000 ms
(node:17208) ExperimentalWarning: SQLite is an experimental feature and might change at any time
(Use `node --trace-warnings ...` to show where the warning was created)
519    w1 job 2 chunk 1/6
1018 w1 gave up on job 2: attempt exceeded 1000 ms. Row is queued again.
1018 w1 handler for job 2 stopped: AbortError
1018 every handler has settled

The handler stops in the same millisecond as the queue, on chunk 1 of 6. One changed line is the whole of cancellation.

Let a second worker claim the job the deadline released.

node queue.mjs run deaf 2 1000

    2 enqueued job 3: handler deaf, 2 worker(s), deadline 1000 ms
  5 w1 claimed job 3, attempt 1, deadline 1000 ms
507    w1 job 3 chunk 1/6
1014 w1 gave up on job 3: attempt exceeded 1000 ms. Row is queued again.
1015 w2 claimed job 3, attempt 2, deadline 1000 ms
1016    w1 job 3 chunk 2/6
1525    w2 job 3 chunk 1/6
1525    w1 job 3 chunk 3/6
2021 w2 gave up on job 3: attempt exceeded 1000 ms. Row is queued again.
…
3088 w1 handler for job 3 returned "charged"
3576    w2 job 3 chunk 5/6
4087    w2 job 3 chunk 6/6
4104 w2 handler for job 3 returned "charged"

From 1525 ms both workers log chunks for job 3. Two executions overlap and both reach the charge. The timeout caused the duplicate.

Cancel a running job from outside, against a deadline far away.

node queue.mjs run coop 1 15000 800

    1 enqueued job 4: handler coop, 1 worker(s), deadline 15000 ms
  4 w1 claimed job 4, attempt 1, deadline 15000 ms
514    w1 job 4 chunk 1/6
826 operator posted /cancel/4
1027    w1 job 4 chunk 2/6
1029 w1 gave up on job 4: cancel requested. Row is queued again.
1029 w1 handler for job 4 stopped: AbortError

POST /cancel/4 sets a flag the worker polls every 200 ms. The abort reached the handler 203 ms later, and the row reads cancel requested rather than a timeout.

Try the other cancel path: stop the worker process.

node queue.mjs kill

    1 enqueued job 5, forking a worker
 10 w-child claimed job 5, attempt 1, deadline 60000 ms
525    w-child job 5 chunk 1/6
1041    w-child job 5 chunk 2/6
1224 parent sends SIGTERM to the worker
1232 child exited code=null signal=SIGTERM
1232 {"id":5,"status":"running","attempts":1,"worker":"w-child","claimed_at":"2026-09-12 18:25:58","finished_at":null}

The child installs a SIGTERM handler that releases the row. On Windows it never ran. code=null signal=SIGTERM is a process killed outright, and the row stays claimed by a worker that is gone.

8
Step 8.
Read the downstream ledger, which no timeout can edit.
```
cat effects.log
```
```
2026-09-12 18:25:45 charged job 1
2026-09-12 18:25:56 charged job 3
2026-09-12 18:25:57 charged job 3
```
Three charges from five jobs. Job 1 was charged after its attempt was declared over, job 3 twice, and the cooperative job 2 is absent.

Read the whole queue, one row per line.

curl -s http://127.0.0.1:8931/jobs | node -e "let s='';process.stdin.on('data',d=>s+=d).on('end',()=>{for(const r of JSON.parse(s))console.log(JSON.stringify(r))})"

{"id":1,"status":"queued","attempts":1,"worker":null,"finished_at":null,"note":"attempt exceeded 1000 ms"}
{"id":2,"status":"queued","attempts":1,"worker":null,"finished_at":null,"note":"attempt exceeded 1000 ms"}
{"id":3,"status":"queued","attempts":2,"worker":null,"finished_at":null,"note":"attempt exceeded 1000 ms"}
{"id":4,"status":"queued","attempts":1,"worker":null,"finished_at":null,"note":"cancel requested"}
{"id":5,"status":"running","attempts":1,"worker":"w-child","finished_at":null,"note":null}

Rows 1 and 2 are identical and their handlers behaved in opposite ways. Row 3 spent two attempts and charged twice. Row 5 stays claimed.

10
Step 10.
Stop the service by the pid from step 1, then confirm it is gone.
```
powershell -Command "Stop-Process -Id 42552 -Force"
curl -s http://127.0.0.1:8931/jobs; echo "curl exit $?"
```
```
curl exit 7
```
Exit 7 is a refused connection. Stop by pid: a stop by image name takes every node process on the machine.

How to read the result

| What you see | What it means | What to do | | --- | --- | --- | | gave up at 1037 ms, returned "charged" at 3078 ms | The deadline fired and the work carried on | Pass the signal into every await in the handler. A timer alone stops nothing. | | handler stopped: AbortError on the same line as the timeout | Cancellation reached the work | This is the passing case. Assert on this line, not on the job row. | | Two returned "charged" lines for one job id | Duplicate execution caused by the timeout | Raise the deadline above the real duration, or key the work as in How to check a background job is idempotent. | | status queued, attempts 2, finished_at null | Two attempts spent, no success recorded | Compare against the downstream ledger. The queue cannot see what the abandoned attempt did. | | status running with a worker that is gone | The process died before it released the row | Reap on claim age. See How to test a stuck background job. | | note: cancel requested | An operator stopped it, no budget was exceeded | Keep the two notes apart in reporting. A retry policy should treat them differently. | | child exited code=null signal=SIGTERM | The shutdown handler did not run | Stop the worker through a message it reads, not a signal. |

Common mistakes

Sign: A timeout test passes because the job row says the attempt failed, and the same work still reaches the payment provider.Cause: The queue and the handler are separate. Here the row read status queued, attempts 1, note attempt exceeded 1000 ms at 1037 ms, while chunk 2 of 6 was logged at 1037 ms and the charge was written at 3078 ms. Assert on a line the handler prints, or on the downstream record, never on the queue row alone.

Sign: The handler catches the abort and branches on e.name === 'TimeoutError', and the branch is never taken.Cause: AbortSignal.timeout aborts with a TimeoutError, but timers/promises rejects with its own AbortError and hangs the original on cause. Measured on Node 22.23.2: the queue side read signal.reason.name = TimeoutError while the handler side read e.name = AbortError, e.code = ABORT_ERR, e.cause.name = TimeoutError. Test signal.reason, or read e.cause.

Sign: Cancelling a job by killing its worker leaves the job claimed and running forever.Cause: A SIGTERM handler that releases the row is not enough on Windows. child.kill('SIGTERM') against a forked Node worker printed no handler output and exited code=null signal=SIGTERM, leaving id 5 with status running and a worker name that no longer exists. Send a stop message the worker reads between jobs, and reap rows by claim age.

Sign: Raising the number of retries makes the duplicate charges more frequent, not less.Cause: Each retry starts a new execution while the previous one is still running, because the deadline released the row rather than stopping the work. Job 3 overlapped two executions from 1525 ms and charged twice. Fix the deadline and the cancellation first. Retry counts multiply whatever the first attempt already does.

What to check next

How to test a stuck background job: a row running with nobody behind it.
How to test duplicate job execution: the duplicate seen from the side effect.
How to test graceful shutdown: the stop message step 7 should have sent.
How to check a background job is idempotent: making the second execution harmless.
How to check if a cron job ran: runs counted against successes.

FAQ

How do I cancel a background job that is already running?

Set a flag the worker reads, and abort a signal the handler honours. In step 6 the worker polled the flag every 200 ms and the handler stopped 203 ms after the request. A job that ignores the signal runs to the end.

What does "job attempt duration exceeded timeout" mean?

The attempt used more wall-clock time than the queue allows, so the queue ended it. That is the queue's decision, not a report that the work stopped: here the work continued for another 2 s.

How do I test a job timeout without waiting for the real budget?

Shorten the deadline instead of lengthening the job. These runs used 1000 ms against 3 s of work and finish in four seconds. Keep the production ratio, not the numbers.

Does aborting the signal undo what the job already did?

No. Abort stops the next step and cannot recall a row written or a request already answered. effects.log kept the charge for job 1 after that attempt was over. What is committed needs compensation or an idempotency key.

Verified

Verified 2026-09-12by Maks Vernynode 22.23.2node:sqlite 3.51.3curl 8.21.0PowerShell 5.1.22621.6133GNU coreutils 8.32

Each output block is what the command above it printed on that date, on the host named in the step. Figures read from a live site move between runs. Compare the shape of the answer rather than the digits, and see the methodology for how a page is re-verified.

All background jobs and queues checkscluster

intermediate12 minpublished 2026-09-12updated 2026-09-12Maks Verny