Chasing a Race Condition That Disappeared Every Time I Added a Log Line

The bug report was two lines: "Sometimes a customer gets two welcome emails. Cannot reproduce."

It happened maybe once in every three hundred signups. Not often enough to be urgent, often enough that support mentioned it every few weeks.

Every time I added logging to find it, it stopped happening.

What the code looked like

async function handleSignup(email, password) {
  const existing = await db.users.findOne({ email });
  if (existing) throw new ConflictError("email already registered");

  const user = await db.users.insert({ email, passwordHash: hash(password) });
  await sendWelcomeEmail(user);
  return user;
}

Read, check, write. Correct in a single threaded test suite. Correct on my machine. Correct every time I stepped through it.

Why logging made it disappear

The window between the read and the insert is tiny, maybe two or three milliseconds. Two requests have to land inside that window for both to see no existing user.

Adding a log line does two things. It adds time to the operation, which sounds like it should widen the window and make the bug more likely. And it adds a synchronisation point, because writing to a stream involves a syscall, which changes how the event loop schedules the two requests relative to each other.

In practice the second effect dominated. The log call reordered execution enough that the two requests stopped interleaving in the specific way required.

This is the general mechanism behind heisenbugs, and it is worth being precise about it rather than treating it as mysterious. Observation is not passive. A log statement is a syscall. A debugger rewrites the machine code and adds trap overhead at every breakpoint. Both change the timing of a system whose bug depends on timing.

For concurrency problems specifically, the debugger is often the worst available tool, because it serialises exactly what you need to observe running in parallel.

The three things that worked

1. Widen the window deliberately

If observation narrows the window, do the opposite. Add a delay in the gap, behind a flag:

const existing = await db.users.findOne({ email });
if (process.env.RACE_DEBUG) await sleep(500);
if (existing) throw new ConflictError("email already registered");
const user = await db.users.insert({ ... });

With a 500ms window, two concurrent requests hit it every time. The bug went from one in three hundred to reproducible on demand.

This is the single most useful technique for suspected races and it feels wrong the first time you do it, because you are making the bug worse on purpose. That is the point. A bug you can reproduce is a bug you can fix, and getting to reliable reproduction is the biggest step change in any investigation.

2. Generate real concurrency in a test

test("concurrent signups with the same email create one user", async () => {
  const email = "[email protected]";

  const results = await Promise.allSettled([
    signup(email, "pw1"),
    signup(email, "pw2"),
  ]);

  const users = await db.users.find({ email });
  expect(users).toHaveLength(1);

  const succeeded = results.filter(r => r.status === "fulfilled");
  expect(succeeded).toHaveLength(1);
});

Two requests, same input, genuinely simultaneous. This failed immediately and it is now a permanent regression test.

Most test suites never run two things at once, which is precisely why concurrency bugs reach production so reliably. Adding concurrency tests for any read-then-write path is cheap and it catches an entire category.

3. Load with contention

For the cases a two request test does not catch:

# 200 requests, 50 concurrent, all identical
hey -n 200 -c 50 -m POST -d '{"email":"[email protected]"}' \
  http://localhost:3000/signup

And add CPU pressure while doing it, which widens timing windows across the board:

stress-ng --cpu 8 --timeout 60s &

The combination of concurrency and contention reproduces things that neither does alone. Same reasoning as flaky tests failing more in CI than locally: a busy machine has wider windows.

The fix

The application level check cannot be made safe. Any read-then-write across a network boundary has a window, and moving the check closer to the write only narrows it.

The database has to decide.

ALTER TABLE users ADD CONSTRAINT users_email_key UNIQUE (email);

async function handleSignup(email, password) {
  let user;
  try {
    user = await db.users.insert({ email, passwordHash: hash(password) });
  } catch (err) {
    if (err.code === "23505") {                    // unique_violation
      throw new ConflictError("email already registered");
    }
    throw err;
  }
  await sendWelcomeEmail(user);
  return user;
}

Attempt the write, handle the constraint violation. The database enforces uniqueness atomically, so there is no window at all.

Note that the check is gone entirely rather than kept as an optimisation. Keeping both means the race still exists on the rare path, and having two mechanisms where one is authoritative invites someone to later remove the wrong one.

For an upsert where you want the existing row rather than an error:

INSERT INTO users (email, password_hash) VALUES ($1, $2)
ON CONFLICT (email) DO NOTHING
RETURNING id;

rowCount of 1 means you created it, 0 means it existed. Atomic, and it is the same pattern that makes webhook handlers idempotent.

The second bug underneath

Fixing the insert did not fix the duplicate emails entirely, and this is the part I nearly missed.

sendWelcomeEmail was outside any transaction. If the email service was slow and the request timed out, the client retried, the insert failed with a conflict, and no second email was sent. Fine.

But if the process restarted between the insert and the email, no email was sent at all. The opposite failure, and nobody had reported it because a missing welcome email produces no support ticket.

The correct shape is to make the side effect part of the same atomic operation, which for an external service means the outbox pattern:

await db.transaction(async (tx) => {
  const user = await tx.users.insert({ email, passwordHash });
  await tx.outbox.insert({
    type: "welcome_email",
    payload: { userId: user.id },
    idempotency_key: `welcome:${user.id}`,
  });
});
// a separate worker drains the outbox

The user row and the intent to send are committed together. A worker reads the outbox and sends, with the idempotency key preventing duplicates if the worker retries.

More machinery than one line of code, and it is the only version that is correct across process restarts.

What I would do differently

Suspect a race whenever a bug is rare, unreproducible, and involves two things happening. That triad is diagnostic. Do not spend an hour trying to reproduce it naturally.

Widen the window before doing anything else. Ten minutes with a sleep behind a flag beats a day of guessing.

Do not reach for the debugger on a concurrency bug. It is the tool most likely to make the bug vanish, and the vanishing feels like progress.

Search the codebase for the pattern once you find one. findOne followed by insert appeared in four other places in the same repository. All four had the same bug. Fixing one and not the others is the most common wasted opportunity in this kind of investigation.

Ask what happens if the process dies at each await. Every await in a handler is a point where the process can stop and never resume. That question found the outbox problem, and it is worth asking routinely rather than only during an incident.