DEV Community

Why Next
Why Next

Posted on • Originally published at blog.whynext.app

The Tests Were Green - the Notification Had Never Been Sent, Not Once

Originally published at blog.whynext.app.

A 500 alert landed in Slack. The error message looked unfamiliar. Error: Custom Id cannot contain :. The API that admins use to post answers to user questions was dying, and the stack trace pointed at BullMQ's Job.validateOptions.

So far, an ordinary bug report. Where this story stops being ordinary is after finding the cause. The code throwing this error had not changed in that day's deploy. It had been failing every time, 100%, since the day the feature first shipped. Which means the push notifications this queue was supposed to send had never been sent, not once. And all that time, every test was green.

The cause was one character

The offending code looked like this. It's the spot where, when a question gets an answer, a job to push-notify the user goes into the queue.

await this.queue.add(ANSWER_NOTIFY_JOB_NAME, data, {
  jobId: `answer-notify:${data.questionId}`, // ← this colon
});
Enter fullscreen mode Exit fullscreen mode

A custom jobId was given so the same question couldn't be enqueued twice, but the delimiter was a colon. BullMQ builds its Redis keys with colons, so it forbids colons in custom jobIds. In v5 the exact condition is: if the jobId contains a colon and splitting on colons does not yield exactly 3 parts, it throws. The 3-part exception is a carve-out for the legacy repeatable-job format, so a 2-part id like answer-notify:123 always gets Custom Id cannot contain :. For the record, purely numeric jobIds are also rejected with Custom Id cannot be integers, so dropping the prefix isn't the answer either.

Dozens of other queues across the codebase all used hyphens. Only this file used a colon.

The bug was there from day one - so why did it blow up today

The fix is one line: change the colon to a hyphen. The interesting question is elsewhere. Why did code that always failed stay quiet all this time and turn into a 500 today?

When the feature first shipped, the enqueue was wrapped like this.

try {
  await this.queue.add(/* ... */);
  return true;
} catch (err) {
  this.logger.error("enqueue failed", err);
  return false; // ← the failure disappears here
}
Enter fullscreen mode Exit fullscreen mode

It logs the failure and returns false. The caller never checks the return value. So the exception that was thrown every time was swallowed every time, the API returned 200, and only the notification quietly evaporated.

Then a commit merged the same day changed this contract. The intent was: if the enqueue fails, don't swallow it, throw, so the "answered" flag written in the transaction gets rolled back and the operation can be retried. A change in the right direction. At that moment, the enqueue that had always been failing made a sound for the first time. The 500 wasn't a bug that commit created - it was the first scream of a bug that had been there all along.

This is the cost of code that swallows errors. The signal disappears, and the bug stays put, taking an entire feature with it.

Why the tests were green

This queue had tests. The usual kind of spec: call the enqueue and check that queue.add was called with the right arguments. And that test's queue.add was a mock that always succeeded.

Real BullMQ's add validates the jobId and rejects colons. The mock's add accepts anything. Exactly as much as the mock was more lenient than the real contract, the tests passed inputs green that could never pass in reality. When a mock diverges from the real contract, a green test certifies dead code, not living code.

While fixing the bug, I plugged this hole first. I changed the queue mock's add to run BullMQ's real Job.validateOptions. That function is pure validation that runs without Redis, so it drops straight into tests. Then I checked that the guard was a real guard with a mutation test. I put the colon back, watched the test turn red at exactly that spot, and only then committed. If you reintroduce the bug and the test is still green, that test might as well not exist.

It wasn't just one

Stopping here would have been fixing half the problem. If the same mistake exists in one place, it probably exists in others. I defined the class of defect - custom jobIds containing colons - swept the whole codebase, and put multiple review agents on it for cross-checking. Two more cases turned up.

One was the queue that transcribes user-uploaded audio to text. jobId: "stt:${id}". This one was still swallowing errors, so there wasn't even a 500. Checking the data showed that for the past 12 days, not a single transcription job had entered the queue. Audio files were saved normally, failures went only to the logs, and on the user's screen the text stayed empty forever. Completely asymptomatic.

The other was the queue for guide emails about scheduled events. Its jobId had four colon-separated parts, so neither reminders nor cancellation notices were entering the queue at all.

I unified the three producers on a single shared jobId builder. It joins with hyphens, replaces any stray colons, and rejects purely numeric ids. To prevent recurrence, I also added a lint rule that catches exactly the pattern of a colon literal inside a jobId. I did not force-migrate the roughly 50 existing hyphen jobIds to the new builder. Changing the jobId of a repeatable job risks duplicate cron registrations, so I chose to target only the defect class.

The second trap: a fixed jobId quietly kills retries

It would have been nice if the story ended there, but during review verification a more fundamental problem surfaced. Once the colon is fixed, a fixed jobId like answer-notify-123 comes alive, and that fixed jobId itself contradicted the retry contract established the same day.

When a job hash with the same jobId still exists in Redis, BullMQ ignores the new add without any error and returns the existing jobId. A verifier confirmed this behavior by reading BullMQ's Lua scripts. But this queue uses removeOnComplete: { count: 100 }, so the hash of a just-completed job stays around. Combine the two and you get this scenario. A notification job fails once. Per the contract, the "answered" flag is rolled back and an admin retries. The new enqueue hits the leftover job hash, does nothing, and returns as if it succeeded. The notification never goes out, and this time there's no error and no DLQ.

Remove the catch that swallowed failures, and the library's dedupe takes over the same role. In the end I removed the custom jobId from this queue entirely. Duplicate-send prevention moved to the consumer side: the processor atomically claims a "notification sent" flag with a conditional update. Even if the job comes in twice, only the side that grabs the flag first sends the push.

If you're preventing duplicates with a custom jobId and you also have a design that re-enqueues on failure, it's worth checking that the two mechanisms don't kill each other. You may have the same combination we did, where a retry quietly becomes a no-op.

What was the damage

A feature dead for 12 days sounds expensive, but the measurements said otherwise. The answer notifications lost zero events, because that feature wasn't in real production use yet. The email queue only covered past events, so there was nothing to resend. The actual recovery scope was 2 untranscribed audio files. The audio was still stored, so re-transcribing them restored everything.

We got lucky. And this luck does not repeat. Had the feature been in active use, 12 days of notifications and transcriptions would have been gone for good, and since the jobs were never created in the queue in the first place, no deploy would have recovered anything. Writing a backfill script was secondary. I judged that the real thing to fix was the fact that a dead feature was dead for 12 days without anyone knowing. So transcription failures no longer stop at the logs and now surface in the alert channel, and the answer-notification path moved to an outbox committed together with the transaction, eliminating the very state of "the DB recorded success but the job doesn't exist".

What it leaves behind

Three things from this incident that will outlast the code.

First, code that only logs in a catch and returns normally makes a path that fails 100% of the time invisible to everyone. If you're going to swallow, at minimum pair it with a metric or an alert that counts the failures, and if you don't have that, throwing is better. A thrown error is loud but gets fixed; a swallowed error lives for 12 days.

Second, mocks must be as strict as the real contract. On top of a mock that always succeeds, no input ever gets validated. If the library ships a pure validation function, run it in the mock, and confirm the test turns red when you reintroduce the bug - that's what makes it a guard.

Third, hunt defects by class. In the same codebase, the same mistake doesn't happen only once. Once you find one, define the class, sweep everything, and go as far as blocking the class from coming back - a lint rule, a shared builder - and one discovery earns its keep.

Top comments (0)