How to test a stuck background job

Read the queue's own table. node jobs.mjs prints every job with its state, how long it has been in that state, the age of its last heartbeat and whether the worker pid still exists. A job in running with a frozen heartbeat and a dead pid is stuck. The same row with a fresh heartbeat is slow.

Why check this

Run this after a worker deployment, after a change to how a job is claimed or acknowledged, and in the regression pass over retries. A worker can die between claiming a row and writing the result, and the row does not change when it does.

It still says running, so the queue counts the job as work in progress. In the run below export-report held that state for 139 seconds after its worker was gone, and charge-card reached attempt 5 against a limit of 3 without reaching failed. One state column cannot separate a slow job from a job nobody is holding.

Prerequisites

• Node 22. node:sqlite prints an ExperimentalWarning on every command below. See its documentation.
• No broker. The queue is one SQLite table and the workers are forked Node processes.
• The queue, with its claim, heartbeat and finish statements. Save as queue.mjs.

// The queue: one SQLite table. Run `node queue.mjs` once to create and seed it.
import { DatabaseSync } from 'node:sqlite';

export const LEASE_MS = 6000;                 // a claim is good for 6 s unless renewed
export const db = new DatabaseSync('queue.db');
db.exec('PRAGMA journal_mode = WAL');         // so a reader can query while workers write
db.exec('PRAGMA busy_timeout = 5000');

export function claim(worker) {
  const now = Date.now();
  return db.prepare(`UPDATE jobs SET state='running', attempts=attempts+1, worker=?, worker_pid=?,
      heartbeat_at=?, lease_expires_at=?, state_changed_at=?
    WHERE id=(SELECT id FROM jobs WHERE state='queued' ORDER BY id LIMIT 1)
    RETURNING id, name, kind`).get(worker, process.pid, now, now + LEASE_MS, now);
}
export const beat = (id) => db.prepare('UPDATE jobs SET heartbeat_at=?, lease_expires_at=? WHERE id=?')
  .run(Date.now(), Date.now() + LEASE_MS, id);
export const finish = (id) => db.prepare(
  `UPDATE jobs SET state='done', state_changed_at=?, heartbeat_at=NULL, lease_expires_at=NULL WHERE id=?`)
  .run(Date.now(), id);

if (process.argv[1].endsWith('queue.mjs')) {
  db.exec(`DROP TABLE IF EXISTS jobs;
    CREATE TABLE jobs (id INTEGER PRIMARY KEY, name TEXT, kind TEXT, state TEXT,
      attempts INTEGER DEFAULT 0, max_attempts INTEGER DEFAULT 3,
      created_at INTEGER, state_changed_at INTEGER, worker TEXT, worker_pid INTEGER,
      heartbeat_at INTEGER, lease_expires_at INTEGER, last_error TEXT)`);
  const now = Date.now(), old = now - 3 * 3600_000;   // job 6 was enqueued three hours ago
  const ins = db.prepare('INSERT INTO jobs (id,name,kind,state,created_at,state_changed_at) VALUES (?,?,?,?,?,?)');
  for (const j of [[1, 'send-invoice', 'fast:2', now], [2, 'rebuild-search-index', 'slow:120', now],
    [3, 'export-report', 'hang:600', now], [4, 'charge-card', 'poison:0', now],
    [5, 'resize-avatar', 'block:30', now], [6, 'send-receipt', 'fast:2', old],
    [7, 'sync-contacts', 'fast:2', now]]) ins.run(j[0], j[1], j[2], 'queued', j[3], j[3]);
  for (const r of db.prepare('SELECT id,name,kind,state FROM jobs').all())
    console.log(`${r.id} ${r.name} kind=${r.kind} ${r.state}`);
}

• The worker. Every kind heartbeats once a second, except poison, which throws, and block, which holds the event loop. Save as worker.mjs.

// One worker. Claims the oldest queued job, renews its lease once a second, marks it done.
import { claim, beat, finish } from './queue.mjs';
const me = process.argv[2];
const t = () => new Date().toISOString().slice(11, 19);
const sleep = (ms) => new Promise((r) => setTimeout(r, ms));

while (true) {
  const job = claim(me);
  if (!job) { await sleep(500); continue; }
  const [kind, secs] = job.kind.split(':');
  console.log(`${t()} ${me} pid=${process.pid} claimed job ${job.id} ${job.name} (${job.kind})`);
  process.send?.({ claimed: job.id, kind });
  if (kind === 'poison') { await sleep(1000); throw new Error('charge-card: gateway said declined'); }
  if (kind === 'block') { const end = Date.now() + Number(secs) * 1000; while (Date.now() < end); }
  else for (let s = 0; s < Number(secs); s++) { await sleep(1000); beat(job.id); }
  finish(job.id);
  console.log(`${t()} ${me} finished job ${job.id} after ${secs}s`);
}

• The pool. Three workers, restarted when they die, one SIGTERM four seconds into the hanging job. Save as run.mjs.

// Three workers under a supervisor that restarts a worker which dies. Arg: seconds to run.
import { fork } from 'node:child_process';
const DEADLINE = Number(process.argv[2] ?? 40) * 1000, started = Date.now();
const t = () => new Date().toISOString().slice(11, 19);
const kids = new Map();
let killed = false;

function start(name) {
  const c = fork('worker.mjs', [name]);
  kids.set(name, c);
  c.on('message', (m) => {                       // kill the worker that took the hanging job
    if (m.kind === 'hang' && !killed) {
      killed = true;
      setTimeout(() => { console.log(`${t()} supervisor SIGTERM ${name} pid=${c.pid} on job ${m.claimed}`); c.kill('SIGTERM'); }, 4000);
    }
  });
  c.on('exit', (code, signal) => {
    console.log(`${t()} supervisor ${name} pid=${c.pid} exited code=${code} signal=${signal}`);
    if (Date.now() - started < DEADLINE - 2000) start(name);
  });
}
['w1', 'w2', 'w3'].forEach(start);
setTimeout(() => { for (const c of kids.values()) c.kill('SIGTERM'); process.exit(0); }, DEADLINE);

• The check itself, with the reaper behind --reap. Save as jobs.mjs.

// The check. `node jobs.mjs` prints the queue; `--reap` also returns abandoned jobs to it.
import { db } from './queue.mjs';
const now = Date.now();
const alive = (pid) => { if (!pid) return '-'; try { process.kill(pid, 0); return 'yes'; } catch { return 'NO'; } };
const sec = (ms) => (ms == null ? '-' : Math.round((now - ms) / 1000));

if (process.argv.includes('--reap')) {
  for (const r of db.prepare("SELECT * FROM jobs WHERE state='running' AND lease_expires_at < ?").all(now)) {
    if (alive(r.worker_pid) === 'yes') { console.log(`job ${r.id} ${r.name}: lease expired, pid ${r.worker_pid} still alive, left running`); continue; }
    db.prepare(`UPDATE jobs SET state='queued', state_changed_at=?, worker=NULL, worker_pid=NULL,
      heartbeat_at=NULL, lease_expires_at=NULL, last_error='lease expired, worker gone' WHERE id=?`).run(now, r.id);
    console.log(`job ${r.id} ${r.name}: worker ${r.worker} pid ${r.worker_pid} gone, attempt ${r.attempts} of ${r.max_attempts} returned to queued`);
  }
}
const p = (v, n) => String(v).padEnd(n);
console.log(p('id', 3) + p('name', 22) + p('state', 9) + p('try', 5) + p('age_s', 7) + p('in_state_s', 12) + p('hb_s', 6) + p('worker', 8) + p('pid', 8) + 'alive');
for (const r of db.prepare('SELECT * FROM jobs ORDER BY id').all())
  console.log(p(r.id, 3) + p(r.name, 22) + p(r.state, 9) + p(`${r.attempts}/${r.max_attempts}`, 5) +
    p(sec(r.created_at), 7) + p(sec(r.state_changed_at), 12) + p(sec(r.heartbeat_at), 6) +
    p(r.worker ?? '-', 8) + p(r.worker_pid ?? '-', 8) + alive(r.state === 'running' ? r.worker_pid : null));

Steps

1. 1

   Step 1.

   Create the table and seed seven jobs.

   node queue.mjs
   

   1 send-invoice kind=fast:2 queued
   2 rebuild-search-index kind=slow:120 queued
   3 export-report kind=hang:600 queued
   4 charge-card kind=poison:0 queued
   5 resize-avatar kind=block:30 queued
   6 send-receipt kind=fast:2 queued
   7 sync-contacts kind=fast:2 queued
   (node:42992) ExperimentalWarning: SQLite is an experimental feature and might change at any time

   send-receipt carries a created_at three hours old, the control for the age column in step 3.

2. 2

   Step 2.

   Start the pool in the first shell for 150 seconds.

   node run.mjs 150
   

   18:06:34 w1 pid=44460 claimed job 1 send-invoice (fast:2)
   18:06:34 w3 pid=15620 claimed job 2 rebuild-search-index (slow:120)
   18:06:34 w2 pid=32608 claimed job 3 export-report (hang:600)
   18:06:36 w1 finished job 1 after 2s
   18:06:36 w1 pid=44460 claimed job 4 charge-card (poison:0)
   …
   Error: charge-card: gateway said declined
     at file:///…/worker.mjs:13:53
   18:06:37 supervisor w1 pid=44460 exited code=1 signal=null
   18:06:37 w1 pid=22228 claimed job 5 resize-avatar (block:30)
   18:06:38 supervisor SIGTERM w2 pid=32608 on job 3
   18:06:38 supervisor w2 pid=32608 exited code=null signal=SIGTERM
   18:06:38 w2 pid=20416 claimed job 6 send-receipt (fast:2)

   Two workers lose their job in two ways. w1 throws and exits code=1. w2 takes a SIGTERM and exits code=null signal=SIGTERM, no handler output. Neither wrote back to its row.

3. 3

   Step 3.

   In the second shell, about 30 seconds in, read the queue.

   node jobs.mjs
   

   id name                  state    try  age_s  in_state_s  hb_s  worker  pid     alive
   1  send-invoice          done     1/3  29     22          -     w1      44460   -
   2  rebuild-search-index  running  1/3  29     24          1     w3      15620   yes
   3  export-report         running  1/3  29     24          21    w2      32608   NO
   4  charge-card           running  1/3  29     22          22    w1      44460   NO
   5  resize-avatar         running  1/3  29     21          21    w1      22228   yes
   6  send-receipt          done     1/3  10829  18          -     w2      20416   -
   7  sync-contacts         done     1/3  29     16          -     w2      20416   -

   Four rows say running and they are four situations. Job 2, heartbeat 1 second old, pid alive: slow. Jobs 3 and 4, heartbeats 21 and 22 seconds old, pids dead: abandoned. Job 5, heartbeat 21 seconds old, pid alive: present and not reporting.

4. 4

   Step 4.

   Run the reaper, which requeues a claim only when its holder is gone.

   node jobs.mjs --reap
   

   job 3 export-report: worker w2 pid 32608 gone, attempt 1 of 3 returned to queued
   job 4 charge-card: worker w1 pid 44460 gone, attempt 1 of 3 returned to queued
   job 5 resize-avatar: lease expired, pid 22228 still alive, left running
   id name                  state    try  age_s  in_state_s  hb_s  worker  pid     alive
   …
   2  rebuild-search-index  running  1/3  37     32          0     w3      15620   yes
   3  export-report         queued   1/3  37     0           -     -       -       -
   4  charge-card           queued   1/3  37     0           -     -       -       -
   5  resize-avatar         running  1/3  37     29          29    w1      22228   yes
   …

   All three leases had expired. Only the two whose worker was gone went back to queued: in_state_s resets while age_s keeps counting. Job 5 kept its claim, because its pid answered.

5. 5

   Step 5.

   Run the reaper twice more, 12 seconds apart, and watch the attempt counter.

   node jobs.mjs --reap
   

   job 4 charge-card: worker w1 pid 40732 gone, attempt 4 of 3 returned to queued
   id name                  state    try  age_s  in_state_s  hb_s  worker  pid     alive
   …
   2  rebuild-search-index  running  1/3  91     87          1     w3      15620   yes
   3  export-report         running  2/3  91     54          0     w2      20416   yes
   4  charge-card           queued   4/3  91     0           -     -       -       -
   …

   The two earlier cycles printed attempt 2 of 3 and attempt 3 of 3. A crash ends the process, so nothing writes failed, and a reaper that only requeues cannot end the loop. Job 3 is running under a new worker with a fresh heartbeat, the recovery this reaper gets right.

6. 6

   Step 6.

   After the pool exits, ask for the same fact in one query.

   sqlite3 -header -column queue.db "SELECT id, name, state, attempts, (strftime('%s','now')*1000 - state_changed_at)/1000 AS in_state_s, (strftime('%s','now')*1000 - heartbeat_at)/1000 AS hb_s, worker, worker_pid FROM jobs WHERE state='running' AND heartbeat_at < strftime('%s','now')*1000 - 15000;"
   

   id  name           state    attempts  in_state_s  hb_s  worker  worker_pid
   --  -------------  -------  --------  ----------  ----  ------  ----------
   3   export-report  running  2         139         22    w2      20416
   4   charge-card    running  5         85          85    w1      3576

   The supervisor signalled its workers at the deadline, so both in flight jobs were abandoned at once. A deployment does the same to a pool.

7. 7

   Step 7.

   Ask the operating system about the worker named in the row.

   Get-Process -Id 20416
   

   Get-Process : Cannot find a process with the process identifier 20416.
   At line:1 char:1
   + Get-Process -Id 20416
   + ~~~~~~~~~~~~~~~~~~~~~
     + CategoryInfo          : ObjectNotFound: (20416:Int32) [Get-Process], ProcessCommandException

   That is the difference between slow and stuck. For a job that is only slow, a process description comes back.

How to read the result

| What you see | What it means | What to do | | --- | --- | --- | | running, heartbeat under 2 s old, pid alive | The job is slow, not stuck | Compare its in_state_s against the same job's usual duration, not against other jobs | | running, heartbeat older than the lease, pid gone | The worker died holding the claim | Requeue it from a reaper that checks the holder, and count the event | | running, heartbeat older than the lease, pid alive | The worker is up and not reporting: a blocked event loop, or a call with no timeout | Do not requeue it. See How to measure event loop lag | | attempts above max_attempts while the state is queued | Nothing records the failure, so the job recycles forever | Write failed and last_error when attempts reach the limit | | Large age_s, small in_state_s | The job waited in the queue and then ran normally | Alert on time in state, never on age | | Many rows queued and none stale | Backlog, not stuck | Measure it with How to check queue depth and consumer lag |

Common mistakes

Thresholds

Set the stale threshold from the heartbeat interval, not from how long jobs take. Fifteen missed beats at one per second is not a busy worker.

What to check next

• How to check if a queue worker is running: the pid column, asked about the pool.
• How to test graceful shutdown: the same kill, done so no job is abandoned.
• How to check queue depth and consumer lag: a backlog when nothing is stale.
• How to test job timeout and cancellation: the deliberate end for a job that overruns.
• How to test duplicate job execution: what a reaper without the pid check causes.

FAQ

How do I tell a long running job from a stuck one?

By the heartbeat and the holder, never by duration. An hour old job with a one second old heartbeat and a live pid is working. The same row with a 21 second old heartbeat and a dead pid is abandoned, as in step 3.

How do I check the status of a background job?

Read the row: state, time in that state, attempts against the limit, the worker and its pid. Step 6 is that query in one line.

What should happen to a job whose worker disappeared?

It goes back to queued with its attempt counted, as in step 4, once the holder is confirmed gone. If that was the last attempt allowed, write failed and the reason instead.

Why does a stuck job keep retrying forever?

Because the crash was never recorded as a failure. In step 5 the counter read attempt 4 of 3 and the state went back to queued: this reaper requeues on an expired lease and never reads max_attempts.

Verified