Case Study 2: Four Minutes of Lag, Six Weeks of Missing Orders
"The extract never failed. It just quietly agreed with itself about where it had got to, and the replica had a different opinion."
Executive Summary
For six weeks in 2025, Kestrel's warehouse was missing roughly 0.04% of orders — about three orders a night, on average, and up to two hundred on the worst nights. Nothing failed. Row counts were normal. The reconciliation against the source, which had been added after the duplicate-rows incident, was showing a small variance that everyone had rationalized as timing.
The cause was replication lag interacting with a watermark. The extract read from a PostgreSQL read
replica — correct practice — and recorded its watermark as the maximum updated_at it observed on
the replica. On nights when the replica fell behind, rows committed on the primary during the lag
window arrived later with timestamps below the stored watermark, and were never read again.
This case study is the anatomy of a bug that produced no errors, no alerts, and a variance small enough to explain away — which is the most dangerous shape a data bug can take. It also examines why the reconciliation that was pointing directly at the problem was disbelieved for five of the six weeks.
Skills applied: replication lag (§4.3); the watermark failure (§4.3, and Chapter 2 §2.3); at-least-once plus idempotency (§4.5); loud versus plausible failure (Chapter 2, Case Study 1).
Background
The extract. platform/ingest/batch/extract_postgres.py pulls incremental changes from
kestrel_app every fifteen minutes:
watermark = read_watermark("orders") # from the warehouse metadata table
rows = replica.execute(
"SELECT * FROM orders WHERE updated_at > %s ORDER BY updated_at",
[watermark],
)
land_to_bronze(rows)
write_watermark("orders", max(r["updated_at"] for r in rows))
Why it reads a replica. Chapter 2 §2.2, question five: a production database serving checkout has capacity you are borrowing. Running a scan every fifteen minutes against the primary is exactly the self-inflicted outage this book warns about. Reading the replica was the right call and remains the right call.
The replica's normal behavior. Asynchronous streaming replication, lag typically 40–200 ms. Monitored, with an alert at 30 seconds that had never fired.
What changed on 2025-08-19. Kestrel's merchandising team began running a nightly bulk price update — 12,000 to 40,000 product rows, in one transaction, at around 01:45. That write burst pushed replica lag to between 90 seconds and four minutes for a few minutes each night.
The lag alert was set at 30 seconds. It fired every night, and because it self-resolved within five minutes and correlated with a known job, it was routed to a low-priority channel within the first week and then ignored. Nobody connected it to anything, because on its own it was harmless: a replica four minutes behind at 01:47 is fine for every consumer that reads it, as long as nobody records a position from it.
The Problem
Here is the exact sequence, on a night when lag reached four minutes.
primary replica extract
│ │ │
01:44:00 txn A commits order 88214 │ │
updated_at = 01:44:00 │ │
│ │ │
01:45:00 bulk price update begins (40k rows) │ │
│ replica starts falling behind │ │
│ │ │
01:46:00 txn B commits order 88215 │ │
updated_at = 01:46:00 │ │
│ │ │
│ 01:46:10 │ has applied │
│ │ up to 01:42:00 │
│ │ │
01:46:15 │◀───── extract runs
│ │ reads rows
│ │ up to 01:42:00
│ │ │
│ │ writes watermark = 01:42:00
│ │ │
01:50:00 bulk update finishes, replica catches up│ │
orders 88214 (01:44) and 88215 (01:46) │ │
now visible on the replica │ │
│ │ │
02:01:15 │◀───── extract runs
│ │ WHERE updated_at > 01:42:00
│ │ -> reads 88214 and 88215 correctly
Read that carefully, because on this timeline nothing is lost. The watermark went backwards relative to the primary, but the next run's filter is inclusive of everything above it, so the delayed rows are picked up.
The loss required one more ingredient, and it took the team three days to find it: the watermark
was written as max(updated_at) of rows actually read, and on a run that returned zero rows the
code did something subtly different.
new_watermark = max(r["updated_at"] for r in rows) if rows else now()
That else now() — added a year earlier to stop the watermark stalling forever if a table went
quiet — is the bug. On a run during the lag window that returned no rows, the watermark was set to
the current wall-clock time on the extract host, which was ahead of the replica's applied position
by the full lag.
01:46:15 extract runs, replica has applied only up to 01:42:00
WHERE updated_at > 01:42:00 -> 0 rows (nothing new applied yet)
rows is empty -> watermark = now() = 01:46:15 ◀── the bug
│
01:50:00 replica catches up. Orders 88214 (01:44) and 88215 (01:46)
become visible, both with updated_at BELOW 01:46:15.
│
02:01:15 extract runs: WHERE updated_at > 01:46:15
88214 and 88215 are invisible. Forever.
Two orders lost, silently, on that night. The number varied with how many orders were placed during the lag window — between zero and about two hundred, averaging around three a night at 01:45, which is a quiet hour.
⚠️ Failure Mode — The defensive line that caused the outage
The
else now()branch was added deliberately, by a competent engineer, to fix a real problem: a low-traffic table whose watermark never advanced, causing the extract to rescan the same empty range indefinitely.It fixed that problem. It also introduced a data-loss path that took fourteen months to manifest, because it only fires when a run returns zero rows and the source is lagging and writes are occurring during the lag window. Three conditions, rarely simultaneous — until a nightly bulk job made the second one routine.
This is the shape of most serious data bugs: a reasonable defensive measure whose failure condition nobody enumerated. The measure was reviewed and approved. What was never asked was under what circumstances is
now()wrong here — and the answer is "whenever the source's clock and the source's applied position disagree," which is always, by an amount that is usually negligible.The general lesson, and it is uncomfortable: every fallback branch is a code path that will execute under conditions you have not imagined. Enumerate them, or do not add the branch.
The Analysis
Why it took six weeks
The nightly source-to-warehouse reconciliation, installed after the duplicate-rows incident, was reporting a variance from day one:
2025-08-20 orders variance: -3 rows (-0.05%) within tolerance
2025-08-21 orders variance: -1 row (-0.02%) within tolerance
2025-08-22 orders variance: -7 rows (-0.11%) within tolerance
...
2025-09-14 orders variance: -204 rows (-3.10%) ALERT
The tolerance was set at 0.5%, chosen when the check was built because small timing differences between a source snapshot and a warehouse load are genuinely normal, and a check that fires every night gets ignored.
Twenty-six nights of small negative variances went unremarked. Each was individually explainable. Nobody looked at the sequence, and the sequence is the finding: a variance that is sometimes positive and sometimes negative is timing noise, and a variance that is always negative is loss.
🔎 Read the Plan — Sign, not magnitude
The reconciliation was measuring the right thing and alerting on the wrong property.
A timing difference between a source snapshot and a warehouse load produces variance in both directions — sometimes the warehouse is momentarily ahead, sometimes behind, and over a month the signed sum is near zero. Loss produces variance in one direction only.
The check that would have fired on day four:
sql -- Alert if the signed variance has the same sign for N consecutive days, -- regardless of whether any single day breaches the tolerance. SELECT COUNT(*) AS consecutive_negative FROM (SELECT variance_rows, ROW_NUMBER() OVER (ORDER BY check_date DESC) AS rn FROM recon_history WHERE table_name = 'orders') WHERE variance_rows < 0 AND rn <= 7; -- 7 of 7 negative: alert, even at 0.02% each.A threshold check asks "is today bad?" A trend check asks "is something systematically wrong?" Most reconciliations only have the first, and the second is where slow leaks show up. Chapter 25 §25.5 covers both.
The diagnosis
Once the 3.1% variance forced attention on 2025-09-14 (a Saturday, after a busier-than-usual Friday night), it took two days:
Day 1. Confirmed the missing orders existed in the source and not in bronze — which located the
failure at ingestion, not transformation, in about ten minutes using the layer-count query from
Chapter 2. Identified that all missing orders had updated_at values clustered between 01:44 and
01:50.
Day 2. That clustering was the entire answer. Cross-referenced against the replication lag graph
— the alert that had been routed to a low-priority channel for six weeks — and the correlation was
exact. Reading the extract code with the lag timeline in hand made the else now() branch obvious.
The lag alert had been correct, and firing, every night for six weeks. It was ignored because in isolation it was harmless. It was harmless in isolation. It was the missing half of a two-part failure, and nothing connected the two parts.
The Decision
Four changes, and the ordering reflects what each is for.
1. The watermark comes from the primary. One cheap query against the primary per run:
# The replica's view of time is not authoritative for "where did I get to".
# Ask the primary what it has committed; read the data from the replica.
safe_upper_bound = primary.execute(
"SELECT now() - interval '30 seconds'").fetchone()[0]
rows = replica.execute(
"SELECT * FROM orders WHERE updated_at > %s AND updated_at <= %s",
[watermark, safe_upper_bound])
land_to_bronze(rows)
write_watermark("orders", safe_upper_bound) # not max(rows)
Two changes in that snippet, and both matter. The watermark is now a bounded range with an upper
bound derived from the primary, rather than an open-ended filter closed by whatever happened to be
read. And the watermark advances to the range's upper bound whether or not rows were found — which
removes the need for the else now() branch entirely.
2. A lag guard. If replica lag exceeds 60 seconds, the extract refuses to run and logs why. It retries on the next fifteen-minute cycle. Failing loudly beats succeeding incorrectly.
3. The overlap margin, as defense in depth. The lower bound is watermark - 5 minutes. This
re-reads a few rows every run, which is harmless because the bronze write is idempotent (upsert on
order_id and log sequence number). This is the at-least-once-plus-idempotency pattern from §4.5
in its most literal form: deliberately accept duplicates in exchange for guaranteed coverage.
4. Sign-based trend alerting on every reconciliation. Seven consecutive same-sign variances alert, regardless of magnitude.
🔁 Idempotency Check — Why the overlap margin is free
Change 3 re-reads five minutes of rows on every run, which at fifteen-minute intervals means roughly a third of every batch is data already loaded.
This costs almost nothing and it is worth being precise about why. The bronze write is an upsert keyed on
(order_id, updated_at). A re-read row produces an update that writes identical values. The extra rows read are a few hundred per run against a table with millions. The extra warehouse work is a merge on rows that do not change.What it buys is that the correctness of the extract no longer depends on the watermark being exactly right — only on it being approximately right, within the margin. That converts a class of subtle, silent, off-by-a-few-seconds bugs into a non-event.
This is the most generally useful trade in ingestion: spend a little redundant work to make correctness robust to timing, and pay for it with an idempotent write. If your write is not idempotent, you cannot make this trade, which is one more reason idempotency comes first.
What Happened
The fixes shipped over four days. The missing orders were recovered by a full re-extract of the
affected six-week window — possible only because kestrel_app retains full order history, which it
does. Had the source been a queue or an API with limited retention, the data would have been gone
permanently.
That deserves emphasis. This bug was recoverable by luck of source-system design, not by anything the platform did. The same bug against the clickstream, whose Kafka retention is seven days, would have permanently lost six weeks of events.
Three follow-on effects:
The sign-based trend check found a second issue within a month — a small persistent positive
variance on fct_shipment, traced to a carrier API returning duplicate tracking records for
multi-package shipments. Small, systematic, and invisible to a threshold check. Same lesson as
Chapter 1's Case Study 2: a check installed for one known problem finds others.
The low-priority alert channel was audited. It contained fourteen alert types, of which four had fired more than a hundred times and none had ever been actioned. Three were deleted, and the other eleven were either re-tuned or promoted. An alert nobody acts on is worse than no alert, because it creates the impression of coverage.
The team added a rule that no alert may be routed to a low-priority channel without a written statement of what would make it important. For the replication lag alert, that statement would have been: "lag matters if anything records a position from the replica" — which would have pointed directly at the extract.
Lessons
-
Never record a position from a lagging replica. Read data from the replica; read the watermark from the primary. This is the exact fix; everything else is defense in depth.
-
Bound your range on both sides. An open-ended
WHERE updated_at > watermarkclosed by whatever was read is fragile. A(lower, upper]range with an upper bound you chose is robust. -
Every fallback branch executes under conditions you have not imagined.
else now()was a reasonable fix for a real problem and it lost data for fourteen months before anyone noticed. -
Sign matters more than magnitude. Timing noise varies in both directions; loss is one-signed. Twenty-six nights of small negative variances were individually explainable and collectively conclusive.
-
Two harmless signals can be one serious failure. The lag alert was correct and ignored; the variance was correct and rationalized. Nothing connected them.
-
An alert nobody acts on is worse than no alert. It manufactures the impression of coverage. Require a written statement of what would make each low-priority alert important.
-
Deliberate duplicate reads plus idempotent writes make correctness robust to timing. The cheapest reliability trade in ingestion, and it is only available if your write is idempotent.
-
Recoverability depended on the source, not on the platform. The same bug against a seven-day-retention topic would have lost six weeks permanently. Know, for every source, how far back you can go.
Questions for Discussion
-
The
else now()branch was added to fix a genuine problem. Write the code review comment that should have caught it, phrased so that it is useful rather than obstructive. -
The reconciliation tolerance was 0.5%, chosen so the check would not fire every night. Was that the right calibration? Design a check that catches this leak without firing on normal timing noise, and state its false-positive rate.
-
The lag alert fired nightly for six weeks and was ignored. Whose failure is that — the person who routed it, the person who set the threshold, or the process? What would you change?
-
Change 3 accepts duplicate reads to make correctness robust. What is the largest overlap margin you would accept, and what would decide it?
-
The data was recoverable only because the source retained history. For each of Kestrel's three sources, state how far back a full re-extract could reach. What should the platform do about the ones with short windows?
-
The new rule requires a written statement of what would make each low-priority alert important. Estimate the maintenance burden of that rule across fifty alerts over three years. Is it worth it, and what would make it not worth it?
-
This bug and the duplicate-rows incident in Chapter 1 have opposite signs — one added rows, one lost them — and the same root shape. State that shape in one sentence, and say what single practice would have caught both.