matrixorigin / matrixorigin/matrixone
[Bug] logservice: log-shard truncation loop can silently stall after snapshotMgr.Count hits MaxExportedSnapshot, causing unbounded WAL growth
- Dominant language
- Go
- Stars
- 1.9k
- Forks
- 311
- Avg merge
- 1d 3h
- Merged PRs (30d)
- 768
Description
## Bug Description
On `freetier-01` (cn-hangzhou), `default-log-0` crashed at **2026-05-02 08:48:45 UTC** with
`no space left on device` and then entered a restart loop that could not self-recover. The
PVC `mo-data-default-log-0` grew from **~2.7 GiB to ~97.9 GiB** over ~59 hours, filling
its 98 GiB volume.
Contrary to first appearances, the growth was not caused by the HAKeeper shard. It was
caused by a **permanent stall** in the log-shard truncation path on this single node:
once `snapshotMgr` fills to `MaxExportedSnapshot=20`, the only way to recover the quota
is a successful `importSnapshot`; on this node the `processShardTruncateLog` loop stopped
producing any log output at all after the stall was reached and never escaped it.
## Environment
- Cluster: `freetier-01`, 3-replica LogSet (`default-log-0`, `default-log-1`, `default-log-3`)
- Image: `v3.0.0-3e1acd5f0-2026-04-29`
- Related prior fix: #24203 / PR #24300 (zombie-replica self-check on startup). This
incident surfaced after the zombie-replica fix merged but is a different root cause.
## Timeline (UTC)
Measured from PVC metrics (`kubelet_volume_stats_used_bytes{pvc="mo-data-default-log-0"}`)
and Loki logs (`{namespace="freetier-01", pod="default-log-0"}`):
| Time (UTC) | Event |
|---|---|
| 04-29 21:24:48 | Last successful `import snapshot success` on log-0. `index=106964377` on `shard=1, replica=1900307`. |
| 04-29 21:24:58 → 21:28:08 | Exactly **20** consecutive `export snapshot success` events (index 106978573 → 106981054). `snapshotMgr.Count(shard=1, replica=1900307) == 20`. |
| 04-29 21:28:08 | Last `export snapshot success` on log-0 for the entire incident window. |
| 04-29 21:33:37 | Rolling restart: log-0 process shut down. |
| 04-29 21:33:44 | log-0 restarted. `snapshotMgr.Init` re-loads the 20 existing `snapshot-XXX/` directories from disk; `Count` remains at 20. |
| 04-29 21:33 → 05-02 08:48 | **59 hours of complete silence** from `processShardTruncateLog` on log-0. Zero `export snapshot success`, zero `import snapshot success`, and — critically — zero of the warn/error branches listed in "Evidence" below. |
| 05-02 08:48:45 | First `no space left on device` panic from dragonboat engine. |
| 05-02 08:48 → (many hours) | Restart loop: tan `open()` tries to rebuild the current logNum, writes `001000.idxtmp`, fails with `no space left`, panics. Cannot self-recover even after k8s restarts the pod. |
During those 59 hours the node's PVC grew at a steady ~1.6 GiB/h. `log-1` and `log-3`
stayed flat in the same window.
## Root cause (code path)
The log-shard truncation loop lives in `pkg/logservice/truncation.go`:
`truncationWorker → processTruncateLog → processShardTruncateLog`.
For a normal log shard the body runs:
```go
// (A) getTruncatedLsn via SyncRead
lsnInSM, err := l.getTruncatedLsn(ctx, shardID)
if err != nil {
err = moerr.AttachCause(ctx, err)
if !errors.Is(err, dragonboat.ErrTimeout) && !errors.Is(err, dragonboat.ErrInvalidDeadline) {
l.runtime.Logger().Error("get truncated lsn in state machine failed",
zap.Uint64("shard ID", shardID), zap.Error(err))
return err
}
return nil // <<<<<< silent swallow; no log, no metric
}
// (B) decide whether to import (preferred) or export
if !l.shouldProcess(shardID, lsnInSM) { return nil }
replicaID := uint64(l.getReplicaID(shardID))
dir, lsn := l.snapshotMgr.EvalImportSnapshot(shardID, replicaID, lsnInSM)
if l.shouldDoImport(ctx, shardID, lsn, dir) {
return l.importSnapshot(...) // path A: import
}
if l.shouldDoExport(ctx, shardID, replicaID) {
return l.exportSnapshot(...) // path B: export
}
return nil
```
`shouldDoExport` enforces a hard cap:
```go
func (l *store) shouldDoExport(ctx context.Context, shardID uint64, replicaID uint64) bool {
if l.snapshotMgr.Count(shardID, replicaID) >= l.cfg.MaxExportedSnapshot {
return false
}
...
}
```
`MaxExportedSnapshot` defaults to **20**.
The failure mode is the interaction between these pieces:
1. Between two successful `importSnapshot` calls the worker exports at most
`MaxExportedSnapshot=20` items. Once `Count==20`, `shouldDoExport` returns false;
only a subsequent `importSnapshot` can lower `Count`.
2. `importSnapshot` requires (a) `lsnInSM` (from TN) to have advanced past the oldest
item's index, and (b) `getTruncatedLsn` (a `SyncRead`) to succeed. If (b) fails with
`ErrTimeout` / `ErrInvalidDeadline`, **`processShardTruncateLog` returns `nil` silently**
— no log, no retry counter, no metric. The tick is effectively a no-op.
3. `snapshotMgr.Count` is persisted indirectly on disk (as the set of `snapshot-XXX/`
directories under `exported-snapshot/shard-S/replica-R/`), so a restart does not reset
the quota. After startup `snapshotMgr.Init` re-scans the directory and rebuilds the
in-memory `items` list at full 20, re-entering the "full and waiting for import" state.
4. Meanwhile the replica is a healthy raft follower. AppendEntries from the shard leader
continue to land and tan rotates `*.log` files normally. Without a successful
`importSnapshot` there is no `nh.SyncRequestImportSnapshot → db.installSnapshot →
removeAllLocked`, so tan never marks old WAL files obsolete and never deletes them.
Net effect once the loop enters this state: **WAL grows linearly at the shard's write
rate; nothing ever reclaims space.** On this node it took ~59 hours to reach the 98 GiB
PVC ceiling.
## Evidence
Measured over the 59-hour window `2026-04-29 21:33:44 → 2026-05-02 08:48:45` on log-0:
| Log pattern | Source | Count |
|---|---|---|
| `export snapshot success` | `truncation.go:142` | **0** |
| `import snapshot success` | `truncation.go:165` | **0** |
| `cannot get leader ID, skip truncate` | `truncation.go:243` | **0** |
| `no leader yet, skip truncate` | `truncation.go:248` | **0** |
| `get truncated lsn in state machine failed` | `truncation.go:260` | **0** |
| `cannot import snapshot, as the replayed LSN is lower...` | `truncation.go:212` | **0** |
| `read state from HAKeeper failed` | `truncation.go:203` | **0** |
| `request export snapshot failed` | `truncation.go:139` | **0** |
| `do truncate log failed` | `truncation.go:275` | **0** |
| `export snapshot failed` | `truncation.go:288` | **0** |
| `HAKeeper shard truncated` | `truncation.go:320` | **30** (every 2h, as expected) |
The only non-silent code path that touches shard 1 is the truncation loop, and it
produced **zero** messages of any severity in 59 hours while the worker was provably
still running (the HAKeeper shard continued to be truncated on the same ticker).
That leaves exactly one possible silent exit path: **`getTruncatedLsn` returning
`ErrTimeout` / `ErrInvalidDeadline`, swallowed by `truncation.go:258-265`**.
This is corroborated by on-disk evidence gathered from the recovered pod:
```
tandb/node-1-1900307/ on disk files (captured at 2026-05-07 11:27 restart)
total files: 3047
.log files: 1523 # fileNum 42584 .. 44107, all consecutive
.index files: 1522
MANIFEST-042593, CURRENT
```
1523 × 64 MiB ≈ 97.5 GiB — matches the PVC ceiling and the incident shape. By contrast
`node-0-131072/` (HAKeeper shard) held only 3 log files (~200 MiB total) at the same
moment: the HAKeeper truncation path (`processHAKeeperTruncation → SyncRequestSnapshot`
with `OverrideCompactionOverhead=true`) is independent and kept working throughout.
## Why log-0 specifically
`log-1` and `log-3` run the same truncation worker against the same shards and did not
fill up. The difference is local: their `processShardTruncateLog` ticks kept succeeding.
Why log-0's `getTruncatedLsn` started returning timeouts and never recovered is a
separate question — candidates include transient raft/ReadIndex issues around the
04-29 21:33 rolling restart, or lingering state from the earlier 04-23 HAKeeper outage
(see #24203) — but the bug in this issue is that **a transient failure at this point is
allowed to degrade into a permanent, unobservable stall**.
## Why this is a bug (not just an ops issue)
- **Unobservable by design.** A persistent failure of the shard truncation loop produces
zero log output at any severity. It is not possible to alert on this today without
bolting on external disk-usage alerts.
- **Not self-healing.** Every tick after the first silent failure continues to be a
no-op for the same reason; there is no retry counter, no escalation, no circuit
breaker. A process restart does not help because the quota is persisted on disk via
the `exported-snapshot/` directory.
- **Hard cap has no escape valve.** `MaxExportedSnapshot=20` is a hard ceiling. When the
loop gets stuck in the "full quota + no import" state there is no mechanism to drop
the oldest snapshot, rotate the quota, or signal an operator.
- **WAL grows at shard write rate until the volume fills**, then the node enters a panic
loop on `no space left on device` that `tan.Open` cannot escape (it tries to write
`*.idxtmp` during rebuild and fails on the same full disk).
## Proposed fix direction
Minimum acceptable change (observability):
1. **`truncation.go:258-265`** — when `getTruncatedLsn` returns `ErrTimeout` /
`ErrInvalidDeadline`, at least log a rate-limited WARN. The current `return nil` is
unobservable.
2. **`truncation.go` (new metrics)** — emit a gauge/counter for
`snapshotMgr.Count(shardID, replicaID)` and for "ticks since last successful
export/import per shard". Either number going monotonic over minutes is a clear
operator signal.
Hardening (optional, recommended):
3. **Escape valve when the quota is full and no import has happened for N ticks.**
Either force an import attempt with fresher diagnostics, or drop the oldest
exported snapshot directory to free one slot (keeping the invariant `Count < 20`).
4. **Widen `getTruncatedLsn` to have its own retry/backoff** instead of relying on the
outer 10-second ticker, so a transient `SyncRead` hiccup doesn't skip a whole tick.
5. **tan side**: when disk is full during `open()` rebuild, fail the replica gracefully
(skip startup of this shard) instead of panicking the whole process. This would at
least break the restart loop and keep the rest of the node usable.
## Workaround (operator)
If a `default-log-N` PVC is observed filling at a steady linear rate while the other
replicas are flat, and `snapshotMgr` is stuck at 20:
1. Scale up the PVC to buy time.
2. Restart the pod (Init rescans and reloads the same 20, does not recover on its own).
3. Manually delete the oldest directory under
`exported-snapshot/shard-S/replica-R/snapshot-XXXXXX/` to free one `Count` slot
and let the worker progress. (This is the "drop oldest" escape valve mentioned
above, applied by hand.)
## Related
- #24203 / PR #24300 — zombie replica self-check on startup. That fix addresses the
04-23 outage class; this issue is a different failure mode in the truncation loop.
Contributor guide
Assessment
This issue has not been assessed yet.