Queue visibility timeout expiry: explain duplicate delivery during slow work

The symptoms

• •Workers report the same job id or message id completing twice in metrics, with completion timestamps closer than the full retry interval.
• •Downstream services receive duplicate writes, notifications, or charge attempts correlated with workers that took longer than the configured visibility window.
• •Application logs show a 'stalled' or 'job recovered' event for a job that the original worker still believes is in flight.
• •Throughput plateaus or declines even when worker CPU and I/O appear underused, because duplicate work cancels out real progress.
• •Retry counters increment without a corresponding failure exception in worker code, indicating the broker re-offered the job rather than the worker releasing it.

Likely causes

• •Job processing logic exceeds the configured lock duration or visibility timeout, after which the broker assumes the worker has died and re-queues the job.
• •Long-running external calls (database transactions, HTTP requests to third-party APIs, file processing) run synchronously without extension or heartbeat.
• •GC pauses, event-loop stalls, or throttled CPU under container quotas cause the worker to miss its lock-renewal deadline, even though the job code is otherwise correct.
• •Concurrency is misconfigured relative to worker capacity, so each in-flight job takes longer than expected because resources are oversubscribed.
• •The job is moved between queues or workers without preserving its lock state, triggering the stalled-job recovery path even though the worker is healthy.

First ten minutes

1. 01Identify which queue and worker pair is showing duplicates by filtering metrics or logs on the specific queue name and worker hostname, not on generic application errors.
2. 02Capture the job's wall-clock processing duration from worker instrumentation and compare it against the configured lock duration or visibility timeout for that queue.
3. 03Pull the 'stalled' or 'job recovered' events from BullMQ's stalled-jobs surface and align their timestamps with the duplicate completion events observed downstream.
4. 04Inspect worker host metrics (CPU steal time, GC pause, event-loop lag, throttling) for the same window to determine whether processing genuinely exceeded the timeout.
5. 05Decide whether to shorten the visible symptom by raising the lock duration or by adding heartbeats, before attempting deeper refactors of the job handler.

Evidence to collect

• •Worker log lines that include job id, queue name, lock duration, and observed processing time for the duplicated job.
• •BullMQ stalled-job events showing the same job id being marked stalled and then moved back to the wait list.
• •Downstream service logs or audit trails showing two write attempts with identical idempotency keys but different worker identifiers.
• •Host-level metrics (CPU throttling, GC pause duration, event-loop lag) for the worker process during the duplicated job's execution window.
• •Queue configuration values: lockDuration, stalledInterval, maxStalledCount, and concurrency for the affected worker class.

Where to look

• •The boundary between the worker process and the BullMQ broker, specifically the lock-renewal heartbeat described in the stalled-jobs documentation.
• •Queue definitions and worker bootstrap code where lockDuration and stalledInterval are set, since these values directly determine the invisibility window.
• •Worker-side timing around external dependencies (database, HTTP, filesystem) where blocking waits can silently exceed the configured window.
• •Container or VM orchestration limits (CPU quotas, memory limits) that can throttle the worker and stretch its processing time.
• •Downstream write paths that accept an idempotency key, because the duplicate delivery only becomes a correctness problem when the side effect is not naturally idempotent.

Diagnostic steps

1. 01Reproduce by enqueueing a job that intentionally sleeps beyond the configured lockDuration and confirm whether the same job id appears on a second worker within the stalledInterval window.
2. 02Compare observed processing time P95 against lockDuration; if P95 is within 20 percent of the lock duration, treat the window as effectively exhausted under load.
3. 03Check whether the duplicated job coincided with a GC pause, event-loop stall, or CPU throttle event by correlating worker timestamps with host metrics.
4. 04Audit the job handler for synchronous external calls that lack a timeout shorter than lockDuration, and verify whether any of those calls can stall indefinitely.
5. 05Verify that downstream write paths accept and honor an idempotency key derived from the job id, so that a recovered job cannot double-charge or double-notify.
6. 06Determine whether concurrency is set higher than the worker host can service within lockDuration by measuring average in-flight job duration under nominal load.

Common mistakes

• •Increasing lockDuration indefinitely instead of bounding the actual work, which delays duplicate delivery rather than preventing it and can mask root-cause slowness.
• •Assuming duplicates are caused by 'at-least-once' delivery in the abstract rather than measuring whether a specific job actually exceeded the configured window.
• •Adding retries on top of duplicate delivery, which amplifies the number of side-effect attempts instead of consolidating them.
• •Catching exceptions inside the job handler and returning success, which prevents BullMQ from moving the job to failed and obscures the stalled-recovery signal.
• •Disabling stalled-job recovery entirely to silence the noise, which removes the only mechanism that re-delivers work from a truly crashed worker.

Safe fixes

• •If measured P95 processing time is consistently above lockDuration, raise lockDuration only to a value that comfortably exceeds P95 plus headroom, and re-measure after the change.
• •If the job handler performs long external work, move that work into a child job or background continuation so the active lock covers only the dispatch step.
• •Add a per-job heartbeat or progress update inside the handler so BullMQ's stalled-job detection can distinguish 'slow but alive' from 'dead'.
• •Bound every blocking external call with a timeout that is strictly less than lockDuration, so a stuck dependency fails fast instead of forfeiting the lock.
• •Make downstream side effects idempotent by deriving an idempotency key from the job id, so duplicate delivery during recovery does not change business state.

Prove the fix

1. 01After the change, run a load test that intentionally holds a job longer than the previous lockDuration and confirm the same job id is NOT delivered to a second worker within one stalledInterval.
2. 02Verify that under sustained production-like load, the duplicate-completion metric for the affected queue drops to zero over a representative window (for example, one hour).
3. 03Confirm that downstream write paths receive exactly one write per logical job, observable via an idempotency key audit log or downstream dedup counter.
4. 04Check that no 'stalled' events are emitted for jobs whose processing time stays below the new lockDuration, indicating the recovery path is no longer firing spuriously.
5. 05Record the before-and-after P95 of worker processing duration, and confirm that headroom between P95 and lockDuration is at least 30 percent.

Prevention and next steps

• •Set lockDuration with explicit headroom over measured P95 processing time, and re-measure whenever the job handler changes.
• •Require every job handler to declare the side effects it performs and the idempotency mechanism that protects each one, reviewed as part of queue onboarding.
• •Alert when duplicate-completion rate for any queue exceeds a small threshold, so silent timeout drift is caught before it causes business-side duplication.
• •Keep external dependency timeouts strictly shorter than the shortest configured lockDuration, and document this constraint alongside queue definitions.

Safe commands and checks

node -e "const q=require('ioredis');const c=new q(process.env.REDIS_URL);c.llen('bull:wait').then(n=>{console.log('wait_list_length',n);return c.quit();})"
node -e "const q=require('bullmq');const c=new q.Queue('email',{connection:require('ioredis').createClient(process.env.REDIS_URL)});c.getJobs(['active','waiting','delayed']).then(j=>{console.log(JSON.stringify(j.map(x=>({id:x.id,name:x.name,ts:x.timestamp}))));return c.close();})"
grep -n "stalled" worker.log | awk '{print $1,$2,$NF}' | tail -n 50
grep -n "jobId" worker.log | sort -k7 | uniq -c | sort -nr | head -n 20
ps -o pid,pcpu,pmem,etime,comm -p <pid>
node --expose-gc -e "const v=require('v8');setInterval(()=>{const s=v.getHeapSpaceStatistics();console.log(JSON.stringify({used:s.map(x=>x.used_space_bytes)}))},1000)"