---
title: "Postmortem: 43 minutes of 502s and one very confident regex"
author: "Dan Whitlock (@grep)"
date: 2025-11-17T08:33:38.256Z
updated: 2025-11-17T08:33:38.256Z
canonical: "https://jot.place/@grep/postmortem-forty-three-minutes-of-502s"
description: "Our gateway returned 502 for forty three minutes because of a regex I would have approved too. Full timeline, the pattern, and the dashboard that lied to me."
tags:
  - "debugging"
  - "postmortem"
  - "sre"
  - "tools"
---

# Postmortem: 43 minutes of 502s and one very confident regex

Published with customer names, hostnames and internal service names removed. Everything else is as filed on 15 May 2026, including the parts that make us look slow.

Times are UTC. Owners are initials. I am DW.

There are initials in the timeline because someone has to be findable afterwards, and no initials in the root cause because a person is not a root cause. If the answer to "why did this happen" is a name, the investigation stopped early. This is the eleventh of these I have written. The table is the only part that gets easier.

## Impact

Forty three minutes, 09:19:40 to 10:02:50 on Thursday 14 May 2026. The public card gateway returned 502 for 24 of those minutes at 100%, and at between 6% and 98% for the rest. At a steady 780 requests per second, about 1.45 million requests failed.

No money moved incorrectly. The gateway fails ahead of the authorisation call and the idempotency layer sits behind it, so nothing was double charged and nothing was captured twice. Merchants retrying during the window got 502 as well, which is the correct outcome and does not feel like one.

Two merchants missed their settlement batch window and were replayed by hand on 15 May.

## Timeline

| Time | Event | Who saw it |
|---|---|---|
| 09:11:02 | Canary of `gateway 2026.5.14-3` to 1 of 34 pods. Canary gate green after 4 minutes. | pipeline |
| 09:14:30 | Rollout to the remaining 33 pods, 6 at a time. Completes 09:18:10. | pipeline |
| 09:19:20 | A merchant's daily retry batch starts. Its reference field ends in base64 padding. | nobody |
| 09:19:40 | First 502. Two pods stop answering readiness probes. | nobody |
| 09:21:05 | Autoscaler goes 34 to 41 pods on CPU. | nobody |
| 09:22:40 | 502 rate at 6%. Liveness starts restarting pods. | nobody |
| 09:23:31 | Support engineer posts "merchant dashboard is throwing errors" in the help channel. | RK |
| 09:25:10 | Autoscaler at 60, the configured maximum. New pods take traffic and stop answering within about 90 seconds. | nobody |
| 09:26:02 | DW starts looking. Latency panel shows p99 at 2.500s, flat. Read as slow. | DW |
| 09:28:44 | 502 rate at 100%. | DW |
| 09:30:12 | DW ties it to the 09:14 rollout. Decision to roll back. | DW |
| 09:31:50 | `GatewayErrorRatioHigh` pages. The condition had been continuously true since 09:20:50. | pager |
| 09:33:05 | Deploy CLI returns 502. It fetches its token through the gateway. | DW |
| 09:36:20 | Break-glass path located in the runbook. It needs a credential nobody on the call held. | DW, MO |
| 09:41:10 | MO has the credential. `kubectl rollout undo` issued. | MO |
| 09:43:20 | One pod held on the new image, pulled out of the load balancer, for later analysis. | DW |
| 09:44:00 | First pods back on `2026.5.14-2`. They stay up. | MO |
| 09:52:15 | 24 of 60 pods on the old image. 502 rate 41%. | MO |
| 09:58:30 | All pods on the old image. | MO |
| 10:02:50 | 502 rate at baseline. Mitigated. | DW |
| 10:19:00 | Autoscaler back to 35 pods. | nobody |
| 11:48:00 | CPU profile from the held pod: 96% of samples inside a single regular expression match. | AF |

## Root cause

A validation pattern added to the shared request middleware nests two unbounded quantifiers over overlapping character classes, so rejecting a value costs roughly twice as much for every additional allowed character that precedes the disallowed one, and one merchant's reference format supplies between 34 and 46 of them.

## The pattern

```text
^([A-Za-z0-9]+[-_ ]?)+$
```

The group takes one or more alphanumerics followed by an optional separator. The outer `+` repeats the group. For a value that is entirely alphanumeric, the number of ways to divide it between repetitions of that group is the number of ordered compositions of its length, $2^{n-1}$. When the value matches, the engine finds one of those divisions immediately and stops. When it does not match, because of a single `=` at the end, the engine has to try all of them before it can say no. At 32 characters that is $2^{31}$ divisions, a little over two billion, which is why the number below reads in seconds.

Measured on my laptop, one core, node, on a string of n alphanumerics followed by one `=`:

| n | time to fail |
|---|---|
| 24 | 99 ms |
| 26 | 398 ms |
| 28 | 1.62 s |
| 30 | 6.46 s |
| 32 | 26.1 s |
| 40 | 1.9 hours, extrapolated |
| 46 | 5 days, extrapolated |

V8 offers no way to abandon a match in progress. Once a worker enters that call, the worker is gone until the process is killed.

The pattern was reviewed by two engineers and shipped with eleven unit tests. All eleven passed in under a millisecond, because all eleven inputs matched. Nobody writes a unit test for a value that gets rejected slowly. That is a property of tests, not of the people who wrote them.

## Contributing factors

1. The middleware runs before routing, on every request, including `/healthz`. No path through the process skipped it.
2. Readiness and liveness are served by the same event loop as customer traffic, so a blocked worker and a dead pod are the same signal. Liveness restarted pods, they came back healthy, took traffic, and blocked again. On a dashboard that looks like recovery.
3. The autoscaler targets CPU. A pegged event loop reads as 100% CPU, so it added pods, and each new pod became another place for a poisoned request to land. We went from 34 pods to 60 and the error rate went up.
4. The canary window did not contain the traffic that triggers the bug. The batch starts at 09:19 and the canary gate closed at 09:15. We do not replay production traffic against canaries.
5. The deploy tool authenticates through the gateway. Rolling back the gateway required the gateway to be working.
6. The break-glass credential was held by two people, neither of them on call. Five minutes of the outage were spent in a direct message.
7. Bodies and headers are capped at 8 KB. Forty six characters was never going to be caught by a limit that generous, and there was no per field limit at all.

## What did not work

The latency panel. The gateway histogram's largest finite bucket boundary is 2.5 seconds, and when a quantile falls in the `+Inf` bucket, `histogram_quantile` returns the upper bound of the second highest bucket. That is documented behaviour and it is exactly what happened: the panel read 2.500 for forty three minutes. I looked at it at 09:26 and concluded we were slow. We were not slow, we were stopped. The rate of the `+Inf` bucket went from about 4 per minute to 61,000 and there was no panel for it.

The alert. `GatewayErrorRatioHigh` carries `for: 10m`, and Alertmanager's default `group_wait` is 30 seconds. The condition became true at 09:20:50 and the page landed at 09:31:50. A support engineer and a dashboard both beat it. The `for: 10m` was set in 2023 after a month of flapping, which was reasonable then and was still there in May 2026, which is the actual problem.

The logs. We log on response. A request that never responds writes nothing, so the last line from a stalled worker is the line before the middleware. Log volume from the gateway went *down* for forty three minutes, which is the opposite of what four people were grepping for.

The runbook. Step 2 is "check recent deploys" and links to a board that lists image deploys sorted ascending by start time. The 09:14 rollout was at the bottom of a scrolling list.

## What we are changing

Dates are commitments. Two action items from a postmortem in 2024 quietly expired in a tracker, so they live in the document now.

- [x] Pattern replaced with a length check and one pass over the bytes. No nested quantifiers anywhere in the middleware. DW, 14 May.
- [x] Per field limit of 64 bytes on merchant references, applied at the edge before validation runs. DW, 15 May.
- [x] Rollbacks now hold one pod out of the load balancer on the build being rolled back, so it can be profiled. DW, 15 May.
- [ ] Readiness served from a separate process on its own port, so a blocked event loop and a dead pod stop being one signal. AF, 29 May.
- [ ] Autoscaler target moved from CPU to in flight requests per pod, with the scale up stabilisation window set to 120 seconds. AF, 29 May.
- [ ] Buckets added at 5, 10 and 30 seconds, and a `+Inf` rate panel placed next to every p99 panel we own. RK, 21 May.
- [ ] `GatewayErrorRatioHigh` moved to `for: 2m` on a one minute window, plus a new page at 5xx above 25% with `for: 0m`. DW, 21 May.
- [ ] A backtracking check in CI, failing the build on any pattern it cannot prove linear. We are trialling `recheck`. MO, 12 June.
- [ ] A deploy path that does not traverse the gateway, credential held by the on call rota rather than by two named people, exercised the first Monday of every month. MO, 12 June.
- [ ] Ten minutes of sampled production traffic replayed against every canary before the gate closes. JS, Q3, not funded, written here so it is on the record.