Lab ST2: Translog and Crash Recovery

Background

The Storage Engine — Intensive chapter and the translog deep-dive told you the theory: an acknowledged write is durable because its op is appended and fsynced to the translog before the 200 OK, and on restart the engine opens the last Lucene commit and replays the translog ops that came after it. In this lab you prove it the only way that really convinces an engineer — you hard-kill the node (kill -9) after acked writes but before a flush, restart, and watch the translog replay restore exactly those un-flushed operations. Then you contrast with data that was flushed (recovered from the Lucene commit, zero translog ops), and reason precisely about what async durability would lose on a power cut.

Why This Matters for Contributors

"Durability" is not a slogan; it is a specific fsync at a specific point in InternalEngine.index(). Contributors who touch the engine, the translog, recovery, or remote store must be able to demonstrate the guarantee and its boundaries. This lab is the muscle memory: induce a crash, read _recovery, count translog ops, and explain every number. It is also the fastest way to build intuition for why index.translog.durability: async is a real (and dangerous) trade.

Prerequisites

An OpenSearch checkout you start with ./gradlew run (so you can kill -9 the JVM and restart it). A tarball/bin/opensearch install works too.
Finished Lab ST1 — you know how to find the shard dir, the translog/ dir, and read _stats.
curl, python3, jps/ps, and the ability to find the ./gradlew run JVM PID.
Read translog.md and recovery.md.

Warning: kill -9 (SIGKILL) is exactly the point — it gives the JVM no chance to flush or clean up, simulating a crash/power loss. A graceful shutdown would flush and prove nothing. Use a disposable dev cluster.

Step-by-Step Tasks

Step 1 — Create an index with explicit, slow flushing

You want writes to land in the translog and stay there (not auto-flush) so the crash happens with un-committed ops. Disable refresh and raise the flush threshold:

curl -s -XPUT 'localhost:9200/durable?pretty' -H 'Content-Type: application/json' -d'
{
  "settings": {
    "index.number_of_shards": 1,
    "index.number_of_replicas": 0,
    "index.refresh_interval": "-1",
    "index.translog.durability": "request",
    "index.translog.flush_threshold_size": "1gb"
  }
}'

request durability ⇒ each bulk is fsynced to the translog before it is acked.
refresh_interval: -1 ⇒ nothing becomes searchable until you ask (separates durable from visible).
flush_threshold_size: 1gb ⇒ a few KB of docs will not trigger an auto-flush.

Step 2 — Find the JVM PID and the shard's translog dir

# The ./gradlew run worker JVM (the actual OpenSearch node):
jps -l | grep -i 'opensearch\|OpenSearch'
#   48213 org.opensearch.bootstrap.OpenSearch
PID=48213

# Data path + shard dir (as in Lab ST1):
DATA=/your/checkout/server/build/run/data
UUID=$(curl -s 'localhost:9200/_cat/indices/durable?h=uuid' | tr -d ' ')
SHARD="$DATA/nodes/0/indices/$UUID/0"
ls "$SHARD/translog"

Step 3 — Index acked-but-unflushed documents

# 500 docs, acked under request durability, fsynced to the translog:
for i in $(seq 1 500); do
  printf '{"index":{"_id":"%d"}}\n{"v":%d}\n' "$i" "$i"
done | curl -s -H 'Content-Type: application/x-ndjson' \
  'localhost:9200/durable/_bulk' --data-binary @- > /dev/null
echo "indexed 500 (acked, fsynced to translog, NOT flushed)"

# Confirm they are in the translog, NOT in a Lucene commit:
curl -s 'localhost:9200/durable/_stats/translog,docs?pretty' \
  | python3 -c 'import sys,json;d=json.load(sys.stdin)["indices"]["durable"]["primaries"];
print("translog ops:", d["translog"]["operations"]);
print("translog uncommitted ops:", d["translog"].get("uncommitted_operations"));
print("lucene docs (committed+segments):", d["docs"]["count"])'

Expected:

translog ops: 500
translog uncommitted ops: 500
lucene docs (committed+segments): 500

Now verify on disk that the translog grew and no new segments_N was written (because we never flushed). Note the current segments_N generation:

ls -la "$SHARD/translog"          # .tlog has grown
ls "$SHARD/index"/segments_*      # remember this generation number

Note: The docs count can show 500 because they are in an in-memory segment buffer, but none of it is in a Lucene commit on disk yet. The only durable record is the fsynced translog. That is precisely what we are about to test.

Step 4 — Hard-kill the node BEFORE any flush

kill -9 "$PID"
# Confirm it's gone:
jps -l | grep -i opensearch || echo "node is dead"

The JVM is gone with no chance to commit Lucene. On disk: an fsynced translog with 500 ops, and a segments_N that predates those 500 docs.

Step 5 — Restart and watch translog replay

./gradlew run     # restart the SAME node on the SAME data path

Watch the startup log for the recovery/replay lines (grep the console or the log file):

# In the run output (or server/build/run/logs/*.log), look for:
grep -iE "recover|translog|existing store|recovered .* operations|recovery.*translog" \
  server/build/run/logs/*.log | tail -20

Expected log shape (wording varies by version — grep, don't memorize):

[durable][0] recovery completed from [existing store], took [123ms]
[durable][0] recovered [500] operations from translog ...   (or "ops-based"/"replayed")
[durable][0] now started ...

The recovery source is "existing store" (local recovery), and it replayed 500 operations from the translog. The Lucene commit had none of them; the translog had all of them.

Step 6 — Confirm the data survived

# All 500 docs are back (refresh first, since refresh_interval was -1):
curl -s -XPOST 'localhost:9200/durable/_refresh' >/dev/null
curl -s 'localhost:9200/durable/_count?pretty'
#   { "count": 500, ... }

# Spot-check a specific id that was only ever in the translog:
curl -s 'localhost:9200/durable/_doc/250?pretty' | python3 -m json.tool
#   "_source": { "v": 250 }, "found": true

The recovery stats name the source explicitly:

curl -s 'localhost:9200/durable/_recovery?human&pretty' \
  | python3 -c 'import sys,json;d=json.load(sys.stdin)["durable"]["shards"][0];
print("type:", d["type"]);                       # EXISTING_STORE
print("stage:", d["stage"]);                     # DONE
print("translog recovered ops:", d["translog"]["recovered"]);
print("translog total ops:", d["translog"]["total"])'

Expected:

type: EXISTING_STORE
stage: DONE
translog recovered ops: 500
translog total ops: 500

You have proven request durability: acked-but-unflushed writes survived a kill -9 and were restored by translog replay, exactly as translog.md describes.

Step 7 — Contrast: data that WAS flushed (Lucene commit)

Now show the other path. Index more, flush (Lucene commit), then crash — and recovery loads from the commit with zero translog ops to replay.

# Index 300 more:
for i in $(seq 501 800); do
  printf '{"index":{"_id":"%d"}}\n{"v":%d}\n' "$i" "$i"
done | curl -s -H 'Content-Type: application/x-ndjson' \
  'localhost:9200/durable/_bulk' --data-binary @- > /dev/null

# FLUSH = Lucene commit + roll + trim translog:
curl -s -XPOST 'localhost:9200/durable/_flush?pretty' >/dev/null

# Translog is now (near) empty — its ops are in the commit:
curl -s 'localhost:9200/durable/_stats/translog?pretty' \
  | python3 -c 'import sys,json;print("translog ops:",
    json.load(sys.stdin)["indices"]["durable"]["primaries"]["translog"]["operations"])'
#   translog ops: 0   (or a tiny number)

# A new segments_N appeared (compare to the generation you noted in Step 3):
ls "$SHARD/index"/segments_*

# Crash again:
PID=$(jps -l | grep -i opensearch | awk '{print $1}'); kill -9 "$PID"
./gradlew run

Check recovery: this time there are ~0 translog ops to replay because everything is in the Lucene commit:

curl -s 'localhost:9200/durable/_recovery?human&pretty' \
  | python3 -c 'import sys,json;d=json.load(sys.stdin)["durable"]["shards"][0];
print("type:", d["type"], "| translog recovered:", d["translog"]["recovered"])'
#   type: EXISTING_STORE | translog recovered: 0
curl -s 'localhost:9200/durable/_count?pretty'
#   { "count": 800, ... }

All 800 docs are present; 0 came from translog replay this time — the 800 were loaded from the committed segments, the post-flush 300 plus the now-committed first 500.

Step 8 — Reason about `async` and power loss

Do not repeat the crash with async and trust the result blindly — instead reason it through, then optionally demonstrate the window.

With index.translog.durability: async (default sync_interval: 5s), the translog is fsynced on a timer, not per request. A 200 OK therefore does not guarantee the op is on disk — up to sync_interval of acked ops sit in OS buffers. A power cut (or kill -9 of the JVM and a host crash that loses the page cache) in that window destroys them, even though the client saw success.

Optional demonstration of the window (this needs the OS to also lose buffered writes to be a true loss; kill -9 of just the JVM does not lose page-cache data, so this shows the concept, with the caveat called out):

curl -s -XPUT 'localhost:9200/risky?pretty' -H 'Content-Type: application/json' -d'
{ "settings": { "index.number_of_shards":1, "index.number_of_replicas":0,
  "index.translog.durability":"async", "index.translog.sync_interval":"30s",
  "index.refresh_interval":"-1", "index.translog.flush_threshold_size":"1gb" }}'

for i in $(seq 1 100); do printf '{"index":{}}\n{"v":%d}\n' "$i"; done \
  | curl -s -H 'Content-Type: application/x-ndjson' 'localhost:9200/risky/_bulk' --data-binary @- >/dev/null
echo "acked 100 under async; fsync only every 30s"

Durability	fsync timing	Crash-loss window	Use when
`request` (default)	before each bulk is acked	none (acked ⇒ on disk)	you need every acked write to survive
`async`	every `sync_interval` (default 5s)	up to `sync_interval` of acked ops on power loss	ingest throughput > strict per-write durability (e.g. reprocessable logs)

Warning: The realistic async failure is power loss / kernel panic, not a JVM kill -9. A kill -9 leaves the data in the OS page cache, which a restart's recovery can still read. To truly observe async data loss you would need to drop the page cache / cut power. State this caveat whenever you demonstrate it — it is a common source of confused "async didn't lose data!" reports.

Deliverables

Startup log lines from the post-crash restart showing recovery ... from existing store and recovered [N] operations from translog.
_recovery output for the un-flushed case (translog.recovered == 500) and the flushed case (translog.recovered == 0).
_count confirming all docs survived both crashes.
A short written explanation: which fsync made the 500 un-flushed docs recoverable, and why the flushed 300 needed no translog replay.
A one-paragraph reasoning of the async + power-loss data-loss window.

Troubleshooting

Problem	Cause	Fix
After restart, `recovered 0 operations` when you expected 500	An auto-flush fired before the crash (threshold/size)	raise `flush_threshold_size`; don't `_forcemerge`/`_flush`; index fewer/smaller
Docs missing after restart	You used `async` and lost the page cache, OR you killed before the bulk was acked	use `request`; ensure the bulk returned 200 before killing
Can't find the JVM PID	`./gradlew run` forks; the worker is `org.opensearch.bootstrap.OpenSearch`	`jps -l \| grep -i opensearch` (not the gradle daemon)
`_count` is 0 but `_recovery` says ops replayed	You forgot to refresh (`refresh_interval: -1`)	`POST /durable/_refresh` — durability ≠ visibility
Restart fails: shard won't allocate	A truly torn translog write (rare)	inspect logs; `opensearch-shard` translog tool; this is a different failure than this lab induces
Recovery takes a long time	Huge translog replayed after the crash	expected — tune `flush_threshold_size`; this is the cost of deferring flush

Expected Output (the headline)

# Un-flushed crash:
type: EXISTING_STORE | translog recovered: 500   ->  count: 500   (saved by translog)

# Flushed crash:
type: EXISTING_STORE | translog recovered: 0     ->  count: 800   (loaded from Lucene commit)

Stretch Goals

Watch the translog files on disk across a flush: note the current translog-N.tlog and segments_M, flush, and observe the generation roll + old-gen trim (translog.md).
Add a replica (number_of_replicas: 1) on a 2-node cluster, kill the primary node, and observe peer recovery instead of local translog replay (recovery.md) — contrast the _recovery type.
Measure recovery time as a function of un-flushed translog size: index 5k, 50k, 500k un-flushed ops and time the post-crash startup. Plot it.
Inspect uncommitted_operations vs operations in _stats/translog before and after a flush and explain the difference.

Coding Exercises

You proved durability with kill -9 and the API. These exercises make you write the tests OpenSearch itself uses to defend the translog-replay guarantee — the code you'd add alongside any engine/translog/recovery change.

(warm-up) A recovery-stats assertion script. Write assert_recovery.py that GETs _recovery?pretty for an index and asserts type == "EXISTING_STORE", stage == "DONE", and translog.recovered == expected. Parameterize expected so the un-flushed case asserts 500 and the flushed case asserts 0. This is Deliverables #1–2 as a re-runnable check.
(warm-up) A translog op-count invariant. Extend the script to GET _stats/translog and assert that uncommitted_operations drops to ~0 after a _flush and equals the un-flushed write count before it. Run it across a flush to prove the "flush trims the translog" claim mechanically.
(core) A translog round-trip unit test. In an OpenSearch checkout, read the real translog tests: rg -l "class TranslogTests|class.*TranslogTest" server/src/test/java/org/opensearch/index/translog/. Write an OpenSearchTestCase that opens a Translog, appends a handful of Translog.Index operations, sync()s, then opens a fresh Translog.Snapshot and asserts every operation reads back identically (same _id, same source). Find the API with rg -n "add\\(|newSnapshot|public .* sync\\(|class Snapshot" server/src/main/java/org/opensearch/index/translog/Translog.java. Run with ./gradlew :server:test --tests '*YourTranslogTest*'.
(core) A translog-replay recovery test. This is the heart of the lab as code. Write an OpenSearchIntegTestCase (InternalTestCluster) that: indexes docs with index.translog.durability: request and a high flush_threshold_size, restarts the node without a flush (internalCluster().restartNode(...) / fullRestart), and asserts via RecoveryResponse that translog.recoveredOperations() equals the un-flushed count and _count is restored. Then a second case that flushes first and asserts recoveredOperations() == 0. Locate patterns with rg -l "restartNode|fullRestart|RecoveryResponse|recoveredOperations" server/src/internalClusterTest/java/org/opensearch/.
(core) Assert the durability fsync ordering. In InternalEngine, find where the translog add/sync happens relative to the ack (rg -n "translog.add|translog.ensureSynced|Durability|REQUEST|maybeFlush" server/src/main/java/org/opensearch/index/engine/InternalEngine.java). Write a unit/integration test (or add an assertion to an existing engine test) that proves, for request durability, the op is fsynced before index() returns — e.g. by asserting the translog's last-synced location advances within the index call. Name the exact method in a comment (this also answers Self-check #1).
(advanced challenge) A fault-injection durability harness. Build a test (or a small driver around InternalTestCluster) that, for a matrix of {request, async} × {flush-before-crash, no-flush}, performs acked writes, simulates a crash (restartNode with a disruption, or a MockFSDirectoryService that drops un-synced data), restarts, and asserts the recovered doc set matches the durability contract: request+no-flush ⇒ all survive; async+no-flush ⇒ may lose the post-sync window (and document the page-cache caveat from Step 8 in the assertion message). Find injection hooks with rg -n "MockFSDirectory|MockEngineSupport|TestTranslog|disrupt" server/src/test/java/ test/framework/src/main/java/. This is the closest a test can get to the power-loss reasoning you did by hand — the rigorous version of the whole lab.

Issues to Practice On

Translog, durability, and recovery are core-repo, under Storage and the distributed/recovery areas. These bugs are correctness-critical, so reproduction and a failing test come first, always.

gh issue list --repo opensearch-project/OpenSearch --label "good first issue" --state open
gh issue list --repo opensearch-project/OpenSearch --label "Storage" --search "translog recovery durability" --state open
gh issue list --repo opensearch-project/OpenSearch --search "translog replay recovery" --state open
gh issue list --repo opensearch-project/OpenSearch --label "flaky-test" --search "recovery" --state open
# Recovery/cluster labels move — confirm on the tracker:
gh label list --repo opensearch-project/OpenSearch | rg -i "storage|recover|distribut|cluster|flaky"

Two representative patterns:

"Data loss / missing docs after a crash or restart." The most serious storage bug class. Reproduce with the Lab ST2 crash workflow, narrow to whether the op was ever fsynced (rg "ensureSynced|durability|translog.add" server/src/main/java/org/opensearch/index/engine/), and ship a recovery test that fails before the fix.
A flaky recovery test. Often a race between flush and crash, or replay ordering. Reproduce under -Dtests.iters=50, locate the replay path with rg "recoverFromTranslog|recoveredOperations|RecoverySourceHandler", and stabilize with a deterministic assertion.

Planted bug exercise. In an OpenSearch checkout, find the durability branch that decides whether to fsync per request (rg -n "Durability|REQUEST|ASYNC|ensureTranslogSynced|maybeSync" server/src/main/java/org/opensearch/index/engine/InternalEngine.java). Change request to behave like async (skip the per-write fsync). Run the engine / recovery tests (./gradlew :server:test --tests '*Translog*' --tests '*Recovery*') and note which goes red. Revert, then add a test that indexes under request, asserts the translog's synced location advanced before the call returned, and would have caught the missing fsync.

Etiquette: claim the issue first, reproduce before fixing, and every PR needs a test + CHANGELOG.md entry + DCO git commit -s. See community interaction and the good-first-issue PR lab.

Validation / Self-check

Which exact fsync makes an acked, un-flushed write survive kill -9? Name the step in InternalEngine.index() (engine-internals.md).
After a flush, why does _recovery report 0 translog ops recovered even though the data is fully present?
Distinguish "durable" from "visible" using the refresh_interval: -1 behavior you saw in Step 6.
State the precise data-loss window of async with a 5s interval, and explain why a JVM kill -9 does not reliably demonstrate it.
Trace the restart recovery: which artifact is opened first, and which ops are replayed on top of it (translog.md)?
If you saw recovered 0 operations in Step 5 unexpectedly, what almost certainly happened, and which setting prevents it?

Open-Source Engineer & Contributor