Skip to content

fix(spurctld): stop logging replayed WAL operations as new events - #785

Open
pre wants to merge 1 commit into
ROCm:mainfrom
silogen:fix/wal-replay-log-noise
Open

fix(spurctld): stop logging replayed WAL operations as new events#785
pre wants to merge 1 commit into
ROCm:mainfrom
silogen:fix/wal-replay-log-noise

Conversation

@pre

@pre pre commented Sep 1, 2026

Copy link
Copy Markdown

Every start of spurctld re-applies the whole Raft log, and each apply logged again at INFO. One node removal was thus printed once per controller process, on every node, with the timestamp of the restart. A reader who greps the journal finds a removal that did not happen, and looks for a fault in the wrong place.

The store now records the highest log index that was on disk at startup. Every entry up to it is a replay, and is applied inside a wal_replay span. The subscriber drops INFO and below inside that span. WARN and ERROR pass, because a bad transition during a replay is a real defect.

The state is applied exactly as before: only the log output changes.

Measured on a three-node cluster: before the change, a restart printed the old "node removed from cluster" line again on every node. After it, a restart that replays 46 entries prints none, sinfo still shows every node, and a live shutdown still logs.

Technical Details

One node removal is printed once per controller process, on every node, carrying the timestamp of the restart rather than of the event:

Aug 31 10:49:15 host spurctld[6618]: INFO spurctld::cluster: node removed from cluster node=worker-3 reason="agent shutdown"
Aug 31 11:39:47 host spurctld[12125]: INFO spurctld::cluster: node removed from cluster node=worker-3 reason="agent shutdown"
Aug 31 11:43:40 host spurctld[12919]: INFO spurctld::cluster: node removed from cluster node=worker-3 reason="agent shutdown"
Aug 31 12:00:02 host spurctld[1241]: INFO spurctld::cluster: node removed from cluster node=worker-3 reason="agent shutdown"

One removal happened. The node was in sinfo the whole time. A reader who greps the journal after a restart finds a removal that did not happen and looks for a fault in the wrong place. This cost real time while diagnosing an unrelated defect, because the replayed line looked like a live event.

The same applies to every other INFO in apply_operation: partitions created, reservations updated, and so on.

SpurStore records the highest log index that was on disk when the process started (replay_upto). Every entry up to it is history, and apply_to_state_machine applies it inside a wal_replay span. The subscriber drops INFO and below inside that span.

WARN and ERROR still pass, because an invalid transition during a replay is a real defect and must stay visible.

Only the log output changes. The state is applied exactly as before.

Test Plan

replay_upto_is_the_highest_index_on_disk fails if the boundary between history and a live event is lost. 963 unit tests pass.

Verified on a three-node cluster:

before after
node removed from cluster in the journal 4, 4 and 7 lines, one per controller start none
the replay itself unchanged raft store recovered from disk log_entries=48 replay_upto=Some(47)
sinfo after the restart 3 nodes 3 nodes, so the state is still applied
a real removal, live logged still logged

The last row is the one that matters: with this change alone on the cluster, an actual node removal still prints its INFO line. The filter hides replayed history, not events.

Test Result

Verification so far, since the workflow runs need maintainer approval:

Local, on this branch alone (rebased on 360d44c):

  • cargo fmt --check --all clean
  • cargo clippy -p spurctld no warnings
  • 963 unit tests pass, including the new
    replay_upto_is_the_highest_index_on_disk

On a three-node cluster, with this change alone and nothing else:

  • A restart that replays 48 log entries prints no node removed from cluster
    line, where before it printed the old one again on every node.
  • raft store recovered from disk log_entries=48 replay_upto=Some(47) shows
    the replay still happens, and sinfo still lists every node afterwards, so
    the state is applied exactly as before.
  • A real node removal, live, still prints its INFO line. This is the case
    that matters: the filter hides replayed history, not events.

The E2E suite has not run yet. Could a maintainer approve the workflow runs?

Submission Checklist

Every start of spurctld re-applies the whole Raft log, and each apply
logged again at INFO. One node removal was thus printed once per
controller process, on every node, with the timestamp of the restart. A
reader who greps the journal finds a removal that did not happen, and
looks for a fault in the wrong place.

The store now records the highest log index that was on disk at startup.
Every entry up to it is a replay, and is applied inside a `wal_replay`
span. The subscriber drops INFO and below inside that span. WARN and
ERROR pass, because a bad transition during a replay is a real defect.

The state is applied exactly as before: only the log output changes.

Measured on a three-node cluster: before the change, a restart printed
the old "node removed from cluster" line again on every node. After it, a
restart that replays 46 entries prints none, sinfo still shows every
node, and a live shutdown still logs.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant