The PR looked correct. We were processing a batch of 50 webhook deliveries sequentially — fetch each one, POST to the destination, mark it delivered. It took about four seconds end to end. The agent opened a PR titled "Parallelize webhook delivery loop" and rewrote the body as a Promise.all over rows.map(processOne).
CI went green. We merged it. p95 batch time dropped from 4.1s to 1.1s. Then the on-call rotation started getting paged for errors that named the wrong webhook.
What the logs said
Every failure in the batch was logged under the same delivery_id. If row 7 timed out, the log line said row 50 timed out. If row 12 returned a 401, the trace attached to that 401 belonged to row 12's parent request, but the delivery_id field said row 50. The dashboard grouped by delivery_id, so one bad row could trigger 50 alerts, and the 401 that should have routed to a customer-config issue got filed under whatever row happened to finish last.
The original code
for (const row of rows) {
logger.child({ delivery_id: row.id });
const res = await fetch(row.url, { method: 'POST', body: row.payload });
await markDelivered(row.id, res.status);
}
The agent "simplified" it to:
await Promise.all(rows.map(async (row) => {
logger.child({ delivery_id: row.id });
const res = await fetch(row.url, { method: 'POST', body: row.payload });
await markDelivered(row.id, res.status);
}));
Both versions call logger.child once per row. The difference is what happens after the first await. In the sequential version, each iteration finishes before the next starts, so the child binding you set before the fetch is still the binding you see after it. In the parallel version, all 50 closures start, each one synchronously rebinds the child, and then they all sit on the event loop waiting for their respective fetch to resolve. By the time any one of them resumes, logger has been rebound 49 times and the final binding — row 50 — is what every continuation sees.
logger.child in most Node logging libraries returns a new child, but if the code was written as logger = logger.child(...) or log.bindings.current = row.id on a shared singleton, the rebinding mutates shared state. The tests passed because the tests asserted on the HTTP calls, not on the log fields.
The cheap fix
Two lines. Don't rebind a shared logger — pass the child explicitly:
await Promise.all(rows.map(async (row) => {
const log = logger.child({ delivery_id: row.id });
const res = await fetch(row.url, { method: 'POST', body: row.payload });
log.info({ status: res.status }, 'delivered');
await markDelivered(row.id, res.status);
}));
Same shape, same parallelism, but each continuation holds its own child instead of reaching back into a mutable singleton. If your logging library supports bound context, this is exactly the case it exists for.
The review question that catches it
When a PR converts a sequential loop to Promise.all or adds concurrency, the line to read isn't the Promise.all itself. It's every line inside the callback that mutates anything outside the loop variable: a module-level logger, a per-request context object, a DB transaction handle, a cache, a counter, an options object reused across iterations. Ask: does this line still do what I think it does when ten copies of it are in flight at once?
We now keep that question as a checklist item in our local API/contract review loop (the same place we re-run recorded HTTP fixtures against the live service before accepting an agent's "refactor done" claim). Most agent "performance" PRs look innocent because they don't change any test assertion — they only change what the production logs and traces look like under real concurrency.
The four-second batch went back to running with a concurrency cap of 4 after this, and each row now holds its own logger child. p95 is still 1.4s. The pages stopped.
