wal: ReadAll resurrects log entries that raft had truncated when the overwriting entry is at or below the snapshot index

Bug report criteria

• This bug report is not security related, security issues should be disclosed privately via the report form.
• This is not a support request or question, support requests or questions should be raised in the etcd discussion forums.
• You have read the etcd bug reporting guidelines.
• Existing open issues along with etcd frequently asked questions have been checked and this is not a duplicate.

What happened?

wal.ReadAll replays the log truncation implied by an overwriting entry (ents = append(ents[:offset], e)) only when that entry's index is strictly greater than the snapshot the WAL was opened at:

https://github.com/etcd-io/etcd/blob/f094b9834a5aa0ef748b91509b824e324dd65700/server/storage/wal/wal.go#L487-L503

case EntryType:
    e := MustUnmarshalEntry(rec.Data)
    if e.GetIndex() > w.start.GetIndex() {
        offset := e.GetIndex() - w.start.GetIndex() - 1
        ...
        ents = append(ents[:offset], e)
    }
    w.enti = e.GetIndex()

When raft overwrites a conflicting suffix (Raft paper figure 7), the WAL records the new entries after the stale ones. If the overwriting entry has an index <= the snapshot index, the if skips it together with the truncation it implies. Stale entries that were written before it, have an index above the snapshot, and were replaced by it in memory (MemoryStorage.Append truncated them) are kept and returned by ReadAll.

Minimal WAL (index/term), written in this physical order:

Save(hs{Term:1, Commit:2}, [1/1 2/1 3/1 4/1 5/1])   // local uncommitted tail 3..5 at term 1
Save(hs{Term:2, Commit:4}, [3/2 4/2])                 // new leader overwrites 3..4; raft truncates 5/1
SaveSnapshot({Index:4, Term:2})                       // local snapshot at applied index 4

Open(snap 4/2) + ReadAll() returns ents = [5/1] instead of []. The raft log rebuilt by bootstrappedWAL.MemoryStorage() (ApplySnapshot(4/2) then Append([5/1])) is [4/2, 5/1]: an entry that raft had discarded is back, and the log terms are no longer monotonic. MemoryStorage.Append does not check terms (go.etcd.io/raft/[email protected]/storage.go:293-326) and newRaft/loadState only validate the commit index (raft.go:2037-2044), so nothing detects it.

The resurrected suffix can also carry a term higher than the snapshot term. Example: node was leader at term 3 and appended 3/3 4/3 5/3 (uncommitted); a new leader at term 4 whose log has 3/2 4/2 backfills them in a first MsgApp (its own no-op 5/4 arrives in a later message because of MaxSizePerMsg), commit advances to 4, the node snapshots at 4/2, then restarts before 5/4 is written. Replay returns [5/3]; log becomes [4/2, 5/3].

The check dates back to the introduction of snapshot records in the WAL (84f62f21e, "wal: record and check snapshot", 2015) and is present on all supported branches (release-3.4 wal/wal.go:453, release-3.5 server/wal/wal.go:449, release-3.6 server/storage/wal/wal.go:486, main :490).

What did you expect to happen?

ReadAll should return exactly the raft log above the snapshot as raft last saw it. An overwriting entry record at index i means raft truncated its log to [..i-1] before appending; every entry read so far with index >= i is stale regardless of where i sits relative to the opening snapshot. In the example above, ReadAll should return [].

How can we reproduce it (as minimally and precisely as possible)?

Unit test against server/storage/wal only (no cluster needed). It is included in the fix PR as TestReadAllDropsOverwrittenSuffixBelowSnapshot in server/storage/wal/wal_replay_test.go.

1. Create a WAL, SaveSnapshot({0,0}).
2. Save(&HardState{Term:1, Commit:2}, [1/1 2/1 3/1 4/1 5/1]).
3. Save(&HardState{Term:2, Commit:4}, [3/2 4/2]) — this is what raft writes when a new leader overwrites the conflicting tail; raft's in-memory log is now [1/1 2/1 3/2 4/2].
4. SaveSnapshot({Index:4, Term:2}), Close, then Open(dir, &walpb.Snapshot{Index:4, Term:2}) and ReadAll().

Expected: ents == []. Actual: ents == [5/1].

A control case with the snapshot taken at 2/1 (i.e. before the overwrite) correctly returns [3/2 4/2], because there the overwriting entries have an index above the snapshot and the truncation is replayed.

Anything else we need to know?

How etcd gets into that WAL shape. etcd snapshots at the applied index (server/etcdserver/server.go:2092 CreateSnapshot(ep.appliedi, ...), :2107 SaveSnap), and applied <= committed <= lastIndex. For a stale suffix to survive, the overwriting batch must end exactly at the snapshot index (any overwriting entry above the snapshot would truncate correctly), so the pattern is: follower has an uncommitted tail from a dead leader, the new leader overwrites part of it and commits up to the end of its batch, the follower applies and takes a disk snapshot at that exact index (snapshot-count threshold crossed on that apply, or ForceSnapshot), then restarts before any further entry is saved. The stale entries are physically earlier in the WAL but openAtIndex/searchIndex selects the segment by first index, so they are within the segments that ReadAll scans. Rare in a busy cluster, but this is a durability-layer correctness bug, and other users of the wal package (embedders that snapshot more aggressively) hit it much more easily.

Consequences once the ghost suffix is loaded.

• Raft's view of its own log is wrong: raftLog.lastEntryID() (log.go:378-385) reports the ghost entry, and isUpToDate (log.go:442-445) compares votes against it. In the first example the node reports last (term 1, index 5) instead of (term 2, index 4). A candidate whose log is 1/1..5/1 (a peer that never received the term-2 entries) is now considered up to date and gets this node's vote (raft.go:1212-1222), whereas the real log would have rejected it. In a 3-member cluster (A = restarted node, B = term-2 leader that committed 3/2 4/2 with A, C = partitioned peer holding 1/1..5/1), C + A form a quorum: C wins at term 3 and B's committed 3/2 4/2 are overwritten by 3/1 4/1 — loss of committed entries. A also accepts C's MsgApp because matchTerm(5, 1) succeeds on the ghost, so A's applied state (which contains 3/2 4/2) diverges from the log it now agrees on.
• The ghost entries are above HardState.Commit, so they are never applied by this node, and the next MsgApp from the legitimate leader removes them through findConflict (log.go:154-167). Heartbeats do not (raft.go:1835-1838). The exposure window is therefore "restart → next real append", which is exactly the window in which elections happen after a restart.
• etcd-dump-logs (tools/etcd-dump-logs/main.go:146) and wal.ReadWALVersion/MinimalEtcdVersion (server/storage/wal/version.go:40, server/storage/storage.go:114) go through the same ReadAll and see the ghost entries.
• --force-new-cluster is not affected: bootstrappedWAL.CommitedEntries() drops everything above commit.

Related gap: received snapshots. When a follower installs a snapshot from the leader, raft replaces its whole log (raftLog.restore, log.go:466-470; MemoryStorage.ApplySnapshot, storage.go:218-237) and etcd writes only a snapshot record to the WAL (server/etcdserver/raft.go:249 SaveSnap, then :256 Save, :277 ApplySnapshot). No entry record encodes that truncation, so a stale uncommitted tail with index above the snapshot index that was in the WAL before the snapshot record is likewise returned by ReadAll after a restart if the node crashes before the leader's next append. Same symptom (ghost suffix above commit, wrong lastEntryID), different trigger. The fix PR addresses both by treating a matching snapshot record whose term differs from the term replay currently has at that index as a full truncation, mirroring raft.restore.

Downstream. This was found through the Formance ledger, which embeds go.etcd.io/etcd/server/v3/storage/wal; the downstream workaround is https://github.com/formancehq/ledger/pull/2076. The upstream fix is in the linked PR.

Etcd version (please run commands below)

Reproduced on main at f094b9834a5aa0ef748b91509b824e324dd65700 (v3.8.0-alpha.0-322-gf094b9834) with a unit test; the code path is identical on release-3.4, release-3.5, release-3.6 and release-3.7.

Etcd configuration (command line flags or environment variables)

N/A (unit test on the wal package).

Etcd debug information (please run commands below, feel free to obfuscate the IP address or FQDN in the output)

N/A

Relevant log output

--- FAIL: TestReadAllDropsOverwrittenSuffixBelowSnapshot/resurrected_suffix_has_lower_term_than_snapshot
    ReadAll(snapshot 4/2) resurrected entries that raft had truncated: got [5/1], want []
--- FAIL: TestReadAllDropsOverwrittenSuffixBelowSnapshot/resurrected_suffix_has_higher_term_than_snapshot
    ReadAll(snapshot 4/2) resurrected entries that raft had truncated: got [5/3], want []