bug: OLR crashes reading online redo with stale/long-lived sequence

[rophy]

Summary

OLR fails with ERROR 50051 did not find lwn at offset when reading online redo logs under heavy write load.

Root Cause Analysis

Theory 1: Stale blocks beyond Oracle write position — DISPROVED

Hex-dump analysis of both XE (10 MB) and RAC (1 GB) redo files shows Oracle does NOT stamp new sequence numbers on old blocks. Old blocks keep their original sequence headers, and checkBlockHeader() correctly returns EMPTY for them. The error offset (8.7 MB) was well within the valid data range of the current sequence.

Theory 2: Read-while-write race on LWN headers — LIKELY

The Parser tracks LWN (Logical Write Number) groups using a chain:

1. Read LWN header at lwnEndBlock (Parser.cpp:1400-1406)
2. Extract lwnSize from offset 28 in the block (4-byte uint32)
3. Set lwnEndBlock = currentBlock + lwnSize for the next LWN
4. If lwnSize is corrupted, lwnEndBlock points to a non-LWN block → ERROR 50051

For online redo, Oracle is actively writing blocks. If OLR reads a block that Oracle is in the process of writing, the lwnSize field (or the vld flag) could be partially written, causing OLR to miscalculate the next LWN position.

This explains:

• Hard to reproduce — requires reading the exact block Oracle is writing at that moment
• Only on online redo — archived redo is fully written, no race
• More likely under heavy load — more blocks being written per second
• The stale thread correlation was coincidental — heavy DML on one node causes rapid redo writes, increasing the chance of a read-while-write collision

Hex-Dump Evidence

Oracle XE (10 MB redo, group 1, seq 142):

Block 2 – 18148:    seq 142 (current) — 8.86 MB of real data
Block 18149 – 20218: seq 140 (old)     — correctly detected as EMPTY by OLR
Block 20219 – 20476: seq 106 (older)   — correctly detected as EMPTY by OLR

Oracle RAC (1 GB redo, group 8, seq 1522):

Block 2 – 1452006:     seq 1522 (current) — 709 MB of real data
Block 1452007 – 1462108: seq 1520 (old)    — correctly detected as EMPTY
Block 1462109 – 1477044: seq 1516 (older)  — correctly detected as EMPTY
Block 1477045+:          seq 0 (zeroes)    — correctly detected as EMPTY

Potential Fix

The Parser should handle (vld & 0x04) == 0 at a valid block (correct sequence, valid CRC) as "block not yet fully written" rather than a fatal error — retry/wait instead of throwing ERROR 50051. This is similar to how the Reader handles EMPTY blocks.

Reproduction

Could not reproduce in 20+ automated attempts. The race window is very small. May need to add intentional delays in the Reader to widen the race window for testing.

Workaround

ALTER SYSTEM SWITCH ALL LOGFILE before starting OLR forces fresh redo files, avoiding any partially-written blocks from a previous write session.

[rophy]

Closing as non-reproducible after thorough investigation.

All three theories disproved:

1. Stale blocks beyond Oracle write position — hex-dump shows old blocks keep old sequence numbers, correctly detected by checkBlockHeader()
2. Read-while-write race on LWN headers — DB_BLOCK_CHECKSUM=TYPICAL and Oracle writes 512-byte blocks atomically
3. RAC code corrupting LWN chain — per-Parser state, no cross-thread contamination

Could not reproduce in 20+ automated attempts. Original failure was likely a transient one-time issue.

[rophy]

Reopened: Bug reproduced and root cause confirmed

Reproduction

1. Start full validation stack (LogMiner + OLR + Swingbench 4 users + validator)
2. OLR crashes within seconds:

processing redo log: group: 7 scn: 16165443 to 0 seq: 1523 path: .../redo_t2_g7.log offset: 1024
ERROR 50051 did not find lwn at offset: 58755072

Root cause: Read-while-write race confirmed

Hex-dump of the crash block after OLR crashed shows:

Block 114756 (offset 58755072):
  seq: 1523 (correct)
  hdr: 0x22 (valid)
  vld: 0x05 (bit 0x04 IS set — valid LWN header)

But OLR threw ERROR 50051 which means (vld & 0x04) == 0 at read time.

Oracle completed writing the block between OLR's read and the file copy. OLR read the block when vld did not have bit 0x04 set, meaning Oracle was in the process of writing the LWN header. The block CRC passed validation because Oracle updates the CRC before (or alongside) the LWN payload fields.

Evidence

This confirms Theory 2 (read-while-write race) which was previously disproved under the assumption that 512-byte writes are atomic with CRC. In practice, Oracle's redo write is NOT fully atomic from OLR's perspective — the CRC can be valid while the LWN vld flag is still being updated.

Fix options

1. Set redo-verify-delay-us > 0 — OLR's built-in double-read verification, designed for exactly this scenario. Default is 0 (disabled).
2. Treat (vld & 0x04) == 0 on online redo as "not ready" — retry/wait instead of throwing ERROR 50051. Similar to how the Reader handles EMPTY blocks.

To test

Add to OLR config:

"redo-verify-delay-us": 10000

[rophy]

Fixed in commit 965b6d08

Root Cause (confirmed)

Read-while-write race on online redo blocks. Oracle writes a block in stages — the block header/CRC can be valid while the LWN vld flag or record size fields are not yet complete. OLR read the block mid-write and crashed.

Proof: Hex-dump of crash block after OLR crashed showed vld=0x05 (valid LWN), but OLR read vld without bit 0x04 at crash time. Oracle completed the write between OLR's read and the file copy.

Fix

In Parser.cpp, when encountering incomplete LWN blocks:

• Online redo (group != 0): treat as "not ready yet" — break and let the Reader re-read the block later. Timeout after 30s with clear error message.
• Archived redo (group == 0): unchanged — throw immediately (a bad LWN in an archive is real corruption).

Validation

• Reproduced consistently before fix (Swingbench 4 users + validator → OLR crashed on attempt 1)
• After fix: 612,092 events matched between LogMiner and OLR, no crashes, no mismatches
• RAC e2e regression: 54 passed, 0 failures