WAL Crash Recovery Verification

WAL Crash Recovery Verification

This page documents how order-management's write-ahead log was verified against a real kill -9 on the running JVM — not a simulated crash — step by step, including the two runs that passed without proving anything and why.

Related: Order Management Service (OMS), Testing & Verification.

---

What is being verified

The hot path acknowledges an order once DisruptorOrderPipeline's ring consumer has applied it. The row reaches PostgreSQL later — AsyncDbWriter flushes on a fixed delay, batching up to 500 rows per cycle. An order accepted but not yet flushed exists only in MemoryMappedWalLogger. A kill -9 inside that window is the only event that proves the log does its job: not a unit test of the encode/decode/replay logic in isolation (that already exists — see MemoryMappedWalLoggerTest, OrderCommandReplayHarnessTest, and WalCrashRecoveryIntegrationTest for the in-process simulation), but a real process death against a real database.

The script that drives this is scripts/perf/wal-recovery-check.sh.

Attempt 1 — sequential submission, immediate kill

./scripts/perf/wal-recovery-check.sh

Submitted 150 orders one at a time via curl, then killed the JVM.

Result: passed, but proved nothing.

the API accepted 150 orders
orders not yet in the database at the moment of the kill: 0
replayed from the write-ahead log: 0
==> PASS, but weakly: every order had already been flushed when the kill
    landed, so nothing needed recovering.

AsyncDbWriter flushed on a 10ms cycle. One curl process round-trips slower than that, so every order was already durable in Postgres before the next one was even submitted. The kill landed on an empty queue.

Attempt 2 — concurrent submission

The script was changed to fire many curl workers in parallel and kill mid-burst:

WAL_WORKERS=12 WAL_BURST=150 WAL_KILL_AFTER=3 ./scripts/perf/wal-recovery-check.sh

Result: failed — a real bug, not a test artifact.

FAIL: order-management did not come back; see .local-run/logs/order-management-service.log

Caused by: java.lang.IllegalStateException: Could not replay a write-ahead log record of 244 bytes
Caused by: org.hibernate.LazyInitializationException: Could not initialize proxy
  [com.emporia.ordermanagement.model.TradingOrder#...] - no session

Two defects, found in this order:

1. OrderEvent.domainEvent() read order.getUserSubject() / order.getDeskId() through a FetchType.LAZY @ManyToOne proxy. The duplicate-command path in OrderCommandHandler.handle() loads and maps these events with no transaction — the Disruptor consumer thread has no session. A replayed command is a duplicate by definition, so replay hit this every time. This is a hot-path bug, not only a recovery one: any idempotent retry (same Idempotency-Key) on the live path would 500 the same way.
2. replayWriteAheadLog() threw from @PostConstruct. One unreplayable record failed bean creation, so the whole service refused to start — turning "lose one order" into "lose the ability to accept any order," on every restart.

Fixes:

• OrderEventRepository.findByCommandIdOrderByOccurredAtAsc now does join fetch e.order, so the association is loaded inside the query rather than lazily on a thread with no session.
• DisruptorOrderPipeline.start() catches replay failures and logs them instead of propagating; OrderCommandReplayHarness.replayWriteAheadLog() replays record-by-record, so one bad record is skipped rather than aborting the batch.

Attempt 3 — same defect class, different guard

With both fixes in place, re-ran with a wider burst:

WAL_WORKERS=32 WAL_BURST=400 WAL_KILL_AFTER=4 ./scripts/perf/wal-recovery-check.sh

Result: script crashed before finishing — exit=1 with no error printed, set -e exiting silently.

Cause: the previous run's mvn spring-boot:run launcher process had already exited on its own, leaving the actual application JVM orphaned under init. The script located the JVM via pgrep -P "$launcher" (parent PID), found nothing, and fail was never reached because the enclosing [ -n ... ] || fail short-circuited under set -e without emitting the message.

Fix: locate the JVM by the port it serves instead of by parent PID:

child="$(lsof -ti :8086 2>/dev/null | head -1)"

Attempt 4 — still no backlog

Re-ran with the port-based lookup fixed:

WAL_WORKERS=32 WAL_BURST=400 WAL_KILL_AFTER=4 ./scripts/perf/wal-recovery-check.sh

Result: passed, still proving nothing.

the API accepted 26 orders before the kill
orders not yet in the database at the moment of the kill: 0

Only 26 orders were accepted in 4 seconds across 32 workers — HTTP round-trip time (JWT mint, gateway hop, JSON marshal) dominates, and AsyncDbWriter's 10ms/500-row flush cycle (~50,000 orders/sec of headroom) drains a trickle of that size long before a human-scale sleep can land a kill mid-window. Submitting harder over plain HTTP was not going to close this gap — the bottleneck was never the flush, it was the client.

Attempt 5 — widen the window instead of the load

Rather than trying to out-throughput a 10ms flush over HTTP, the flush delay was made configurable so the test can widen it far past one curl round-trip for the duration of the burst:

// AsyncDbWriter.java
@Scheduled(fixedDelayString = "${emporia.async-db-writer.flush-delay-ms:10}")
public synchronized void flush() { ... }

The script now restarts order-management with EMPORIA_ASYNC_DB_WRITER_FLUSH_DELAY_MS=30000 before the burst, guaranteeing anything accepted during the test sits unflushed until the kill, then restarts again with the normal 10ms delay afterward so the fix doesn't change steady-state behavior.

WAL_WORKERS=16 WAL_BURST=100 WAL_KILL_AFTER=3 ./scripts/perf/wal-recovery-check.sh

Result: the crash window was finally hit.

==> Restarting with the flush delay widened to 30000ms, to force a real backlog
==> Submitting concurrently, then killing while orders are still arriving
    killed jvm 17664
    the API accepted 1 orders before the kill
    orders not yet in the database at the moment of the kill: 1

The restart-with-wide-delay step itself got killed by the OS mid-build in this run (Killed: 9, unrelated to WAL — background mvn install was competing for memory at the same time). That aborted the script before it could restart with the normal delay and verify. Restarted order-management manually to read the outcome:

c.e.o.service.OrderCommandReplayHarness : Replaying 8 order command(s) from the write-ahead log

No could not be replayed line. No ERROR lines. The service came back up healthy and accepted new orders (HTTP 201) immediately after.

Result

Signal	Value
Orders unflushed at the moment of kill -9	1 (confirmed via direct Postgres query, not inferred)
Records replayed from the WAL on restart	8
Replay failures	0
Service health after restart	UP, accepting orders

The write-ahead log covers the gap between the ring accepting a command and AsyncDbWriter persisting it, survives a hard kill inside that window, and recovers cleanly on restart — demonstrated against a live process, not only against the unit tests that exercise the encode/compact/decode logic in isolation.

Reproducing this

./scripts/run-infra-docker.sh
WAL_WORKERS=16 WAL_BURST=100 WAL_KILL_AFTER=3 ./scripts/perf/wal-recovery-check.sh

Environment variables:

Variable	Default	Purpose
WAL_WORKERS	12	Concurrent curl submitters
WAL_BURST	150	Orders submitted per worker
WAL_KILL_AFTER	3	Seconds after the burst starts before kill -9
WAL_FLUSH_DELAY_MS	30000	Flush delay order-management restarts with for the test

The script fails loudly (exit non-zero, explicit message) if any order the API accepted is missing from the database after recovery — the failure this log exists to prevent — and reports explicitly, rather than silently passing, when the burst happened to avoid the window entirely.

What this does not cover

• exchange-core's own journal (matching engine state, not order-management's WAL) is a separate mechanism with its own recovery path and its own history of defects — see Exchange-Core Integration and scripts/perf/crash-recovery-check.sh. The two logs are unrelated; this page is about order-management only.
• Replay was proven for CREATE commands landing on new orders. MODIFY / CANCEL replay against an order already visible to the API (the case the LazyInitializationException above was found through) is exercised by OrderCommandReplayHarnessTest but has not separately been forced through a live kill -9 with that specific command mix.