The transaction that committed in the past: how I diagnosed one bug six times in an evening

This is a submission for DEV's Summer Bug Smash: Smash Stories powered by Sentry.

There is a special kind of bug that doesn't crash anything. No exception, no error log, no red dashboard. The system hums along, green across the board — and quietly throws away your data.

This is the story of one of those, in a change-data-capture engine I build in Rust — a system that reads Oracle's redo logs byte-by-byte, off the database, and replicates committed transactions to warehouses and streams. Its one sacred promise: if Oracle committed it, we deliver it.

One June evening, a test proved the promise was a lie. Over the next three hours and thirteen minutes I diagnosed the bug six times. Only the first was right — and I dismissed it, then chased four wrong theories, caught myself in an embarrassing hex-arithmetic error halfway through, and circled all the way back to where I'd started. The trail of wrong turns is preserved, in real time, in my commit history, and I'm going to walk you through all of it, timestamps and all, because the wrong turns are the story.

Up front, so you know what you're reading: the engine is closed-source, so there's no repo to hand you. But every commit message I quote below is real — lifted verbatim from that evening's git history, wrong arithmetic and all. Internal tool and ticket names are the only things I've changed.

The setup

Two weeks earlier I had shipped the engine's real-time mode: instead of waiting for Oracle to archive a redo log and reading it cold, the tailer polls the live online redo log every few hundred milliseconds — decoding a file while Oracle is still writing it. Median commit-to-decoded latency: 238 ms. I was very proud of it.

Polling a live file means re-decoding an ever-growing window, which means seeing the same transactions again on every poll. So the tailer deduplicated across polls the obvious way: remember the highest commit SCN you've emitted (Oracle's System Change Number — a monotonically increasing clock stamped on every change), and on the next poll, skip everything at or below that floor.

Simple. Obvious. Wrong in a way that took me six theories — and a full circle back to the first — to prove.

20:03 — Theory #1: it's the dedup floor

A long-transaction test went red: open a transaction, leave it open while a dozen short transactions commit, then commit it. The engine captured the twelve short ones and silently dropped the long one. The archived-log path captured it fine — this was real-time-mode only.

My first commit that evening documented a suspicion that will sound very smart in about three hours:

"the windowed re-decode dedups by a scalar commit-SCN floor … the txn's insert is released under that prior (low) commit SCN, and once the floor passes it the row is pruned forever. … **Proper fix is a design change: dedup by transaction identity … not a scalar SCN floor."

I wrote down the correct fix, in the first twenty minutes, in the commit message. Then I spent the rest of the evening talking myself out of it — because my repro was dirty in a way I didn't yet understand, and clean-looking evidence was about to point somewhere much scarier.

20:17 — Theory #2: no, it's the core decoder

I tightened the repro with unique per-run markers, re-ran, and the new evidence said the dropped row's commit_scn equaled its insert SCN — not its real commit SCN. Worse: the batch path decoding the very same log showed the same wrong value. This wasn't a real-time dedup quirk. This was the core decoder stamping the wrong commit SCN on any transaction held open while others commit.

I escalated it in the log: core decode bug, affects every path, do not rush the fix. The dedup-floor theory from 14 minutes ago? Officially a red herring, "misled by cross-run contamination." (Hold that phrase.)

20:27 — Theory #3: a single wrong byte

If the decoder stamps the wrong SCN, find where. I dumped the raw redo with ALTER SYSTEM DUMP LOGFILE and went byte-level. (A held-open transaction is an IMU — in-memory undo — transaction: Oracle buffers its redo privately and flushes begin + insert + commit as one unit at commit time.) The dump was unambiguous: the row's true SCN was 0x150b4a1 everywhere it mattered, but the decoder emitted 0x150b2a1 — a value that appears nowhere in the log. One byte off. My commit concluded the parser was mis-framing the record, and helpfully wrote out the decimal conversions of both hex values.

One of those conversions was wrong. Nobody noticed. Especially not me.

20:31 — Theory #4: the byte is fabricated downstream

Four minutes later, an offline probe over the preserved log killed Theory #3: the parser framed the record perfectly. Every change-vector SCN in that record was correct. The mystery value 0x150b2a1 matched no header anywhere in the file — so it wasn't mis-read, it was fabricated somewhere downstream in event assembly. I listed three candidate functions and narrowed the hunt.

I was now hunting the origin of a value that did not exist. For a very good reason.

20:42 — Theory #5: the pivot

"That was a HEX-CONVERSION ERROR on my part: 0x150b4a1 = 22066337 (the CORRECT commit SCN), not 0x150b2a1. The held-open IMU transaction actually decodes CORRECTLY."

There it is, verbatim, the most embarrassing commit message I have ever written — and the most valuable. Fifteen minutes earlier, doing arithmetic in my head at 20:27, I had converted 0x150b4a1 to the wrong decimal and then pinned the correct decimal onto the wrong hex string. The decoder had been right all along. The "single wrong byte" was in my head. The batch path was fine; the caveats I'd splashed across three docs got withdrawn.

Which meant the bug was real-time-only after all… and I still hadn't found it. Two reasoned fixes had already failed — implemented, 140 tests green, repro still red, reverted. My commit ends with a change of method that decided the whole hunt:

"the next step is an OFFLINE poll-simulation over the preserved corpus to pin the exact drop and iterate the fix fast (not rebuild-and-pray)."

21:52 — Theory #6: the ghost with four timestamps

I spent the next seventy minutes building instead of guessing: I split the tailer's dedup core into a pure function an offline test could drive, and built a serializer that dumps a live mid-write window — the exact bytes the tailer saw mid-poll — to a file that replays deterministically offline.

The offline simulation immediately proved the sealed decode and the dedup path were both correct on any static snapshot. And the live trace showed something spectacular: the same id=1000 row appearing poll after poll with a different, increasing commit SCN each time — 22087937 → 22089678 → 22090175 → 22090911. One row, four commit timestamps. A transaction whose commit kept moving.

New theory, stated with great confidence: when a held-open transaction's own commit record is still beyond the write head, the assembler mis-attributes its commit SCN to the latest visible commit. The row is right, the metadata is wrong, the floor prunes it. Q.E.D.

It's a beautiful theory. It survived exactly eighty-four minutes.

23:16 — What the NOTE column said

The test table had a NOTE column I'd been ignoring — each test run writes a unique random marker into it. I finally dumped it for those four "re-attributed" rows:

r1854822674_long, r878629041_long, r348217387_long, X3647_long.

Four different markers. Four different runs.

Oracle's online redo logs are circular — a "new" log is a recycled one, still holding valid-looking blocks from previous incarnations. Every run of my test did DROP TABLE … PURGE, CREATE, insert id=1000. So four runs' worth of stale id=1000 rows were sitting in the log, landed in one decode window, and read as "one row whose commit SCN keeps changing." There was no re-attribution. There was no moving commit. The centerpiece evidence of Theory #6 was four different transactions wearing the same primary key.

And with the ghosts exorcised, the live trace of the current run finally showed the actual smoking gun, small and undramatic:

held-open txn:  commit_scn = 22103071   ← correct, its own, real
dedup floor:                 22103185   ← already past it

A transaction held open while others commit gets its commit record written after theirs — so it becomes readable last with an SCN from the past. It commits earlier in SCN time, later in file time. By the time its commit surfaced in the window, the scalar floor — advanced by the younger transactions that beat it into the file — had already rolled past it, and the dedup pruned it as "already seen."

Theory #1. From 20:03. The one whose correct fix I wrote into my first commit message and then abandoned because a dirty repro made better theories look true. The bug was never in the decode, never in the framing, never a wrong byte, never a mis-attribution. It was the floor, all along, exactly as first suspected — only now proven, with a trace that distinguished this run's transaction from its four dead ancestors.

The fix

Dedup by transaction identity, not by a scalar SCN watermark. The tailer now tracks emitted: HashMap<TxId, commit_scn>, self-bounded each poll to transactions still decodable in the window (anything that aged out of the circular log can never reappear, so it needn't be remembered). A transaction is emitted iff its commit TxId hasn't been — so an out-of-SCN-order held-open commit can never be pruned by younger neighbors:

CaptureMessage::Commit { tx_id, scn } => {
    let already = emitted_txns.contains_key(tx_id);   // identity, not an SCN floor
    if !already {
        emitted_txns.insert(tx_id.clone(), scn.0);
        group.push(m);
        out.append(&mut group);
    }
    group.clear();
}

The regression test encodes the whole evening in fourteen lines: poll 1 emits a transaction committed at SCN 200; poll 2 surfaces a held-open commit at SCN 150 — below the highest already emitted — and asserts it must still come out:

let out2 = select_new_messages(poll2, &mut txns, &mut ddl);
assert_eq!(
    commit_scns(&out2),
    vec![150],
    "held-open commit (150) emitted though it is below the already-emitted 200"
);

The long-transaction gate flipped from KNOWN-FAIL to a mandatory passing gate: 2/2, three consecutive runs, on a live containerized Oracle 23ai. 145 unit tests green, p95 poll latency 248 ms — the fix costs nothing measurable.

And the offline window-replay tool, built at 21:52 to chase a bug that turned out not to exist? Its inability to reproduce the drop on any static snapshot was the strongest clue that the decode was innocent. Sometimes the most useful thing a tool can tell you is "not here."

What I keep from that evening

1. The log remembers your old experiments. Circular buffers, recycled logs, reused primary keys — any repro that can't distinguish this run from previous runs will eventually hand you fiction. One unique marker per run turned three hours of ghost-hunting into one SELECT.
2. Give your first theory the same rigor as your last. I wrote the correct diagnosis and the correct fix in the first commit — then abandoned them because contaminated evidence made a scarier theory look stronger. Theories aren't refuted by newer theories; they're refuted by clean evidence.
3. When rebuild-and-pray fails twice, stop and build a replay harness. The serializer + offline simulator took one focused hour and ended a hunt that guessing would have extended indefinitely.
4. Write the wrong turns down. Every one of these quotes is a real commit message from that evening, wrong arithmetic and all. That paper trail is why I can tell you this story — and why the post-mortem took ten minutes instead of a week.

The transaction that committed in the past ships on time now. Its commit SCN is lower than its neighbors'; its identity is its own; and there's a HashMap that will never forget it — for exactly one window, and not a poll longer.

What's the longest you've chased a bug that turned out to be your test harness lying to you? I want to hear the war story in the comments. 👇

This is one of my two Summer Bug Smash entries. The other is a Clear the Lineup fix — a year-old Zulip bug that six contributors tried before me — where the hard part wasn't the code, it was finishing what everyone else started.

---

Written up from that evening's git history (2026-06-18, 20:03–23:16). The engine is a from-scratch Rust CDC system that decodes Oracle redo logs off-database; this real-time path was already live in production, which is exactly what made a silent, deniable transaction drop worth three hours of hunting.