SDSTOR-22293: handle logdev recovery corner case

conanfile.py

@@ -9,7 +9,7 @@
 
 class HomestoreConan(ConanFile):
     name = "homestore"
-    version = "7.5.12"
+    version = "7.5.13"
 
     homepage = "https://github.com/eBay/Homestore"
     description = "HomeStore Storage Engine"

docs/incidents/bug-logdev-truncate-chunk-meta-inconsistency.md

@@ -0,0 +1,142 @@
+# RCA: LogDev Crash on Restart — Truncation Chunk/Meta Inconsistency
+
+**Date:** 2026-05-22
+**Component:** HomeStore / LogStore / JournalVirtualDev
+**Severity:** Critical (crash on restart, blocks recovery)
+
+---
+
+## Symptom
+
+After a SIGKILL, the process crashes during restart at `log_dev.cpp:234`:
+
+```
+Assertion failure: Expected '473577' to be == to '460780'
+log indx is not the expected one
+```
+
+`do_load` reads the first log group from the persisted start dev_offset
+(`0x54BC8000`) and finds `start_idx=473577`, but the logdev superblock says
+`log_idx=460780`.
+
+---
+
+## Root Cause Chain
+
+### Condition 1: `m_vdev_jd->truncate()` persists chunk metadata synchronously
+
+`JournalVirtualDev::Descriptor::truncate()` calls `update_chunk_private()` for
+every chunk it modifies. The call chain:
+
+```
+update_chunk_private()
+  → chunk->set_user_private()
+    → write_chunk_info()
+      → physical_dev->write_super_block()
+        → m_drive_iface->sync_write()   ← synchronous disk write
+```
+
+Specifically, truncation:
+1. Marks the new head chunk `is_head=true` — **sync_write**
+2. Calls `release_chunk_to_pool()` on each removed chunk, which clears its
+   private data — **sync_write** per chunk
+
+All writes complete before `truncate()` returns.
+**Evidence:** `physical_dev.cpp:122` — `sync_write` call, no async path.
+
+### Condition 2: `m_logdev_meta.persist()` is called after `m_vdev_jd->truncate()` returns
+
+`LogDev::truncate()` (`log_dev.cpp:665–688`):
+
+```cpp
+m_vdev_jd->truncate(min_safe_ld_key.dev_offset);   // chunk state durable
+
+// ← SIGKILL WINDOW OPENS HERE
+
+m_logdev_meta.set_start_dev_offset(..., false);     // in-memory only
+m_logdev_meta.unreserve_store(..., false);           // in-memory only
+m_logdev_meta.remove_rollback_record_upto(..., false); // in-memory only
+
+m_logdev_meta.persist();    // ← logdev superblock written; never reached
+```
+
+When `stopping=false` (normal operation), all intermediate calls use
+`persist_now=false`. Only the final `persist()` writes to disk.
+**Evidence:** code structure, `log_dev.cpp:665–688`.
+
+### Condition 3: On restart, stale logdev meta is interpreted against a new chunk list
+
+`JournalVirtualDev::init()` rebuilds the chunk list from on-disk chunk private
+data (not from logdev meta). After the truncation in Condition 1, the new head
+chunk is persisted. On restart:
+
+- **Chunk list (from disk):** `[Chunk B (is_head=true), ...]`
+  (Chunk A was released and its private data cleared/persisted to disk)
+- **Logdev meta (from disk):** `(dev_offset=0x54BC8000, log_idx=460780)`
+  (old value, persist never ran)
+
+`LogDev::start()` calls:
+```cpp
+m_vdev_jd->update_data_start_offset(0x54BC8000);  // set from stale meta
+m_log_idx = 460780;
+do_load(0x54BC8000);
+```
+
+### Condition 4: `offset_to_chunk(0x54BC8000)` maps to Chunk B in the new list
+
+`journal_vdev.cpp:727`:
+```cpp
+chunk_aligned_offset = round_down(m_data_start_offset, chunk_size);
+off_l = 0x54BC8000 - chunk_aligned_offset;
+// Iterates [Chunk B, ...] → maps to Chunk B at offset off_l
+```
+
+The old offset `0x54BC8000` is now interpreted against the new chunk list. It
+maps to a physical position inside Chunk B, where log data starting at
+`start_idx=473577` resides.
+
+### Condition 5: `do_load` has no handler for `header->start_idx() > m_log_idx`
+
+`log_dev.cpp:225–234`:
+```cpp
+if (loaded_from == -1 && header->start_idx() < m_log_idx) {
+    // handles: journal fully truncated → break
+}
+// No handling for start_idx > m_log_idx ← the actual case (473577 > 460780)
+HS_REL_ASSERT_EQ(header->start_idx(), m_log_idx.load(), ...);  // CRASH
+```
+
+The assert fires because the gap case (truncation advanced further than what
+is recorded in meta) is unhandled.
+
+---
+
+## Trigger Conditions
+
+The following sequence must all occur:
+
+1. LogDev has at least two chunks in its journal chunk list
+2. A truncation is triggered (raft compact or resource pressure) where
+   `min_safe_ld_key.dev_offset` falls in chunk N+1 or later (i.e., the
+   truncation point crosses a chunk boundary, causing chunk N to be released)
+3. SIGKILL arrives after `m_vdev_jd->truncate()` returns but before
+   `m_logdev_meta.persist()` executes
+
+The window is narrow (microseconds to low milliseconds) but non-zero, and
+SIGKILL is unblockable.
+
+**Observed instance (2026-05-10):**
+- `log_dev=1`, pre-kill flush at `log_idx=490277`
+- Truncation with `min_safe_ld_key.idx=475195`
+- Persisted meta: `(dev_offset=0x54BC8000, log_idx=460780)`
+- First log in new chunk list: `start_idx=473577`
+
+---
+
+## Skipped Conditions
+
+None. All four conditions confirmed via static code analysis and log evidence.
+The chunk list change (Condition 3) is proven by the crash itself via proof by
+contradiction: if the chunk list had not changed, `offset_to_chunk(0x54BC8000)`
+would map to the original Chunk A and recover log 460780 correctly; the
+observed mismatch is impossible without a chunk list change.

src/lib/device/journal_vdev.cpp

@@ -566,7 +566,7 @@ void JournalVirtualDev::Descriptor::update_tail_offset(off_t tail) {
     LOGINFOMOD(journalvdev, "Updated tail offset arg 0x{} desc {} ", to_hex(tail), to_string());
 }
 
-off_t JournalVirtualDev::Descriptor::truncate(off_t truncate_offset) {
+off_t JournalVirtualDev::Descriptor::truncate(off_t truncate_offset, logid_t log_idx) {
     const off_t ds_off = data_start_offset();
     COUNTER_INCREMENT(m_vdev.m_metrics, vdev_truncate_count, 1);
     HS_PERIODIC_LOG(DEBUG, journalvdev, "truncating to logical offset: 0x{} desc {}", to_hex(truncate_offset),
@@ -605,6 +605,14 @@ off_t JournalVirtualDev::Descriptor::truncate(off_t truncate_offset) {
     auto* private_data = r_cast< JournalChunkPrivate* >(const_cast< uint8_t* >(new_head_chunk->user_private()));
     private_data->is_head = true;
     private_data->logdev_id = m_logdev_id;
+    if (log_idx != -1) {
+        // Write recovery hint so do_load can handle a crash between this truncation and
+        // the subsequent logdev meta persist. Only written when log_idx is known.
+        private_data->head_version = JournalChunkPrivate::JOURNAL_HEAD_VERSION;
+        private_data->head_magic = JournalChunkPrivate::JOURNAL_HEAD_MAGIC;
+        private_data->head_start_offset = truncate_offset;
+        private_data->head_start_idx = log_idx;
+    }
     m_vdev.update_chunk_private(new_head_chunk, private_data);
 
     // Find all chunks which needs to be removed from the start of m_journal_chunks.
@@ -807,6 +815,11 @@ nlohmann::json JournalVirtualDev::Descriptor::get_status(int log_level) const {
     return j;
 }
 
+const JournalChunkPrivate* JournalVirtualDev::Descriptor::head_chunk_private() const {
+    if (m_journal_chunks.empty()) { return nullptr; }
+    return r_cast< const JournalChunkPrivate* >(m_journal_chunks.front()->user_private());
+}
+
 std::string JournalVirtualDev::Descriptor::to_string() const {
     off_t tail =
         static_cast< off_t >(data_start_offset() + m_write_sz_in_total.load(std::memory_order_relaxed)) + m_reserved_sz;

src/lib/device/journal_vdev.hpp

@@ -35,11 +35,21 @@ using journal_id_t = uint64_t;
 // Each log device has a list of journal chunk data with next_chunk.
 // Journal vdev will arrange the chunks in order during recovery.
 struct JournalChunkPrivate {
+    // Fields below are the original on-disk layout (must stay at these offsets).
     logdev_id_t logdev_id{0};
     bool is_head{false};       // Is it the head element.
     uint64_t created_at{0};    // Creation timestamp
     uint64_t end_of_chunk{0};  // The offset indicates end of chunk.
     chunk_num_t next_chunk{0}; // Next chunk in the list.
+
+    // Head chunk recovery hint appended after the original fields.
+    // Only valid when is_head==true and head_magic==JOURNAL_HEAD_MAGIC.
+    static constexpr uint32_t JOURNAL_HEAD_VERSION{1u};
+    static constexpr uint32_t JOURNAL_HEAD_MAGIC{0xBEEFCAFE};
+    uint32_t head_version{0};
+    uint32_t head_magic{0};
+    off_t head_start_offset{0}; // logdev truncate offset persisted with head
+    logid_t head_start_idx{0};  // logdev truncate idx persisted with head
 };
 
 static_assert(sizeof(JournalChunkPrivate) <= chunk_info::user_private_size, "Journal private area bigger");
@@ -286,7 +296,7 @@ class JournalVirtualDev : public VirtualDev {
          *
          * @return : return the new data start offset after truncation.
          */
-        off_t truncate(off_t truncate_offset);
+        off_t truncate(off_t truncate_offset, logid_t log_idx = -1);
 
         /**
          * @brief : get the total size in journal
@@ -332,6 +342,8 @@ class JournalVirtualDev : public VirtualDev {
 
         logdev_id_t logdev_id() const { return m_logdev_id; }
 
+        const JournalChunkPrivate* head_chunk_private() const;
+
         std::string to_string() const;
 
     private:

src/lib/logstore/log_dev.cpp

@@ -233,6 +233,52 @@ void LogDev::do_load(off_t device_cursor) {
             break;
         }
 
+        if (loaded_from == -1 && header->start_idx() > m_log_idx) {
+            // Corner-case recovery: a SIGKILL landed after vdev chunk truncation (durable) but
+            // before logdev meta persist.  The chunk list reflects the new head; logdev meta
+            // still carries the old (dev_offset, log_idx).  We validate via the recovery hint
+            // written atomically into the head chunk during truncation and then advance m_log_idx
+            // to match the first log group the stream reader actually found.
+            THIS_LOGDEV_LOG(WARN,
+                            "LogDev {} corner-case recovery: header->start_idx()={} > m_log_idx={} "
+                            "(stale meta dev_offset={}); validating head chunk recovery hint",
+                            m_logdev_id, header->start_idx(), m_log_idx.load(), device_cursor);
+
+            auto const* hint = m_vdev_jd->head_chunk_private();
+            HS_REL_ASSERT(hint, "logdev={} corner-case recovery: head chunk hint is missing; possible data corruption",
+                          m_logdev_id);
+            HS_REL_ASSERT(hint->is_head && hint->head_magic == JournalChunkPrivate::JOURNAL_HEAD_MAGIC &&
+                              hint->head_version == JournalChunkPrivate::JOURNAL_HEAD_VERSION,
+                          "logdev={} corner-case recovery: start_idx={} > m_log_idx={} but head chunk hint is invalid "
+                          "(magic=0x{} version={} is_head={}); possible data corruption",
+                          m_logdev_id, header->start_idx(), m_log_idx.load(), to_hex(hint->head_magic),
+                          hint->head_version, hint->is_head);
+            HS_REL_ASSERT_GT(hint->head_start_idx, m_log_idx.load(),
+                             "logdev={} corner-case recovery: hint->head_start_idx={} must be > stale m_log_idx={}",
+                             m_logdev_id, hint->head_start_idx, m_log_idx.load());
+
+            THIS_LOGDEV_LOG(
+                WARN, "LogDev {} corner-case recovery: advancing m_log_idx {} -> {} data_start_offset {} -> {}",
+                m_logdev_id, m_log_idx.load(), hint->head_start_idx, device_cursor, hint->head_start_offset);
+
+            // Scope and known limitations of this recovery:
+            // - This fix is scoped to logstream positioning only. The following meta changes
+            //   from the aborted LogDev::truncate() are NOT replayed here:
+            //   * start_dev_offset / log_idx: not persisted here. The corner-case recovery
+            //     path is idempotent — the hint in the head chunk remains valid across
+            //     restarts until the next successful truncation persists consistent meta.
+            //   * unreserve-store: garbage store IDs self-heal at handle_unopened_log_stores()
+            //     on this restart and are removed at the next truncation.
+            //   * rollback-info cleanup: stale records remain semantically valid because
+            //     logids are monotonically increasing and never reused, so no false positives
+            //     can occur. Cleaned up at the next truncation.
+            m_log_idx.store(hint->head_start_idx, std::memory_order_release);
+            m_vdev_jd->update_data_start_offset(hint->head_start_offset);
+            device_cursor = hint->head_start_offset;
+            do_load(device_cursor);
+            return;
+        }
+
         THIS_LOGDEV_LOG(DEBUG, "Found log group header offset=0x{} header {}", to_hex(group_dev_offset), *header);
         HS_REL_ASSERT_EQ(header->start_idx(), m_log_idx.load(), "log indx is not the expected one");
         if (loaded_from == -1) { loaded_from = header->start_idx(); }
@@ -637,7 +683,7 @@ uint64_t LogDev::truncate() {
         auto lstore = store.log_store;
         if (lstore == nullptr) { continue; }
         auto const [trunc_lsn, trunc_ld_key, tail_lsn] = lstore->truncate_info();
-        m_logdev_meta.update_store_superblk(store_id, logstore_superblk(trunc_lsn + 1), stopping /* persist_now */);
+        m_logdev_meta.update_store_superblk(store_id, logstore_superblk(trunc_lsn + 1), false /* persist_now */);
         // We found a new minimum logdev_key that we can truncate to
         if (trunc_ld_key.idx < min_safe_ld_key.idx) { min_safe_ld_key = trunc_ld_key; }
     }
@@ -664,8 +710,29 @@ uint64_t LogDev::truncate() {
 
     uint64_t const num_records_to_truncate = uint64_cast(min_safe_ld_key.idx - m_last_truncate_idx);
 
+    // Persist per-store start LSN before vdev truncation to avoid the following:
+    // If store superblocks are not persisted here and we crash after vdev truncate but before the
+    // final persist below, corner-case recovery still fixes logstream positioning via the head-chunk
+    // hint, but Raft start_index() loads a stale (too-low) m_first_seq_num from disk, making this
+    // node appear to retain more logs than it actually does and potentially triggering baseline resync.
+    m_logdev_meta.persist();
+
     // Truncate them in vdev
-    m_vdev_jd->truncate(min_safe_ld_key.dev_offset);
+    m_vdev_jd->truncate(min_safe_ld_key.dev_offset, min_safe_ld_key.idx);
+
+#ifdef _PRERELEASE
+    // Simulate a crash after vdev chunk truncation (durable) but before the final persist that
+    // updates logdev start_dev_offset. Per-store start LSN was already written above.
+    if (hs()->crash_simulator().crash_if_flip_set("abort_logdev_truncate_before_meta_persist")) {
+        THIS_LOGDEV_LOG(INFO,
+                        "CRASH FLIP fired: vdev truncated to dev_offset={} log_idx={} but logdev start offset "
+                        "not persisted. Stale logdev offset on disk: dev_offset={} log_idx={}",
+                        min_safe_ld_key.dev_offset, min_safe_ld_key.idx, m_logdev_meta.get_start_dev_offset(),
+                        m_logdev_meta.get_start_log_idx());
+        decr_pending_request_num();
+        return num_records_to_truncate;
+    }
+#endif
 
     // Update the start offset to be read upon restart
     m_last_truncate_idx = min_safe_ld_key.idx;