Missing log replay on single-node restart (bug?)

[schreter]

I'm not sure if it's really a bug in openraft, but we are seeing unapplied committed log entries in single-node mode.

Our setup looks like this:

• we have a state machine, which does not persist the changes right away, but rather delayed/at snapshot
• log entries are of course persisted immediately
• at startup, the state machine lags behind the log and entries need to be re-applied

Due to a bug in our code the vote was not reconstructed properly upon restart in a single-node unit test. This led to an "election" where the node was first deemed a Follower with is_leader == false and immediately afterwards changed to Leader. At this time, the openraft sent also Apply command to the state machine worker to apply the missing log up to the end (after writing log entry 8 with new term for itself).

After fixing vote recovery (reading committed vote for itself), the is_leader is set to true and also log end is detected properly (log entry 7). However, there is no Apply command sent to the state machine worker and the committed index is also not advanced (stays at None), so the test fails immediately because it doesn't find the expected data in the state machine.

This is all with current openraft master and latest Rust version. It happens on all our OSes (M1/M2/M3 MacOS and x64/aarch64 Linux).

I suppose, there is something missing when handling shortcuts for single-node Raft with a state machine that doesn't immediately apply entries persistently. I.e., my expectation would be that openraft would issue Apply command to apply the log in range (None, 7) and to set committed index to 7 as well, if it's a single-node system. I suppose, merely updating the leader state is missing, i.e., it should set the committed index to log end in this case, which would then trigger Apply command for the state machine worker and apply the missing log.

@drmingdrmer Can you please check? Or are we doing something wrong?

Thanks in advance.

---

Here some snippets from the traces (I tried to remove the irrelevant instrumentation):

"Successful" startup (with wrong vote with node index 0, which is invalid):

DATE  INFO RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:startup: openraft::engine::engine_impl: .../openraft/src/engine/engine_impl.rs:144: startup begin: state: RaftState { vote: Leased { data: Vote { leader_id: LeaderId { term: 3, voted_for: Some(NodeIndex(0)) }, committed: true }, last_update: Some(Instant(Instant { tv_sec: 860983, tv_nsec: 320042875 })), lease: 0ns, lease_enabled: true }, committed: None, purged_next: 0, log_ids: LogIdList { key_log_ids: [LogId { leader_id: CommittedLeaderId { term: 0, p: PhantomData<raft_types::NodeIndex> }, index: 0 }, LogId { leader_id: CommittedLeaderId { term: 3, p: PhantomData<raft_types::NodeIndex> }, index: 1 }, LogId { leader_id: CommittedLeaderId { term: 3, p: PhantomData<raft_types::NodeIndex> }, index: 7 }] }, membership_state: MembershipState { committed: EffectiveMembership { log_id: Some(LogId { leader_id: CommittedLeaderId { term: 0, p: PhantomData<raft_types::NodeIndex> }, index: 0 }), membership: Membership { configs: [{NodeIndex(1)}], nodes: {NodeIndex(1): NodeId[::b:0:0:0:16]} }, voter_ids: {NodeIndex(1)} }, effective: EffectiveMembership { log_id: Some(LogId { leader_id: CommittedLeaderId { term: 0, p: PhantomData<raft_types::NodeIndex> }, index: 0 }), membership: Membership { configs: [{NodeIndex(1)}], nodes: {NodeIndex(1): NodeId[::b:0:0:0:16]} }, voter_ids: {NodeIndex(1)} } }, snapshot_meta: SnapshotMeta { last_log_id: None, last_membership: StoredMembership { log_id: None, membership: Membership { configs: [], nodes: {} } }, snapshot_id: "" }, server_state: Learner, io_state: IOState { building_snapshot: false, io_progress: IOProgress { accepted: Some(Log(LogIOId { committed_vote: CommittedVote { vote: Vote { leader_id: LeaderId { term: 3, voted_for: Some(NodeIndex(0)) }, committed: true } }, log_id: None })), submitted: Some(Log(LogIOId { committed_vote: CommittedVote { vote: Vote { leader_id: LeaderId { term: 3, voted_for: Some(NodeIndex(0)) }, committed: true } }, log_id: None })), flushed: Some(Log(LogIOId { committed_vote: CommittedVote { vote: Vote { leader_id: LeaderId { term: 3, voted_for: Some(NodeIndex(0)) }, committed: true } }, log_id: None })) }, applied: None, snapshot: None, purged: None }, purge_upto: None }, is_leader: false, is_voter: true
DATE  INFO RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:startup: openraft::engine::engine_impl: .../openraft/src/engine/engine_impl.rs:166: startup done: id=NID[1] target_state: Follower
...
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:report_metrics: openraft::core::raft_core: .../openraft/src/core/raft_core.rs:628: report_metrics: Metrics{id:NID[1], Follower, term:3, vote:<T3-NNID[0]:Q>, last_log:7, last_applied:None, leader:None(quorum_acked_time:None), membership:{log_id:0.0, {voters:[{NID[1]:NodeId[::b:0:0:0:16]}], learners:[]}}, snapshot:None, purged:None, replication:{None}, heartbeat:{None}}
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:report_metrics:current_leader: openraft::core::raft_core: .../openraft/src/core/raft_core.rs:698: get current_leader self_id=NID[1] vote=<T3-NNID[0]:Q>
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:report_metrics:current_leader: openraft::core::raft_core: .../openraft/src/core/raft_core.rs:718: id=NID[0] is not a voter
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:report_metrics: openraft::core::raft_core: .../openraft/src/core/raft_core.rs:628: report_metrics: Metrics{id:NID[1], Follower, term:3, vote:<T3-NNID[0]:Q>, last_log:7, last_applied:None, leader:None(quorum_acked_time:None), membership:{log_id:0.0, {voters:[{NID[1]:NodeId[::b:0:0:0:16]}], learners:[]}}, snapshot:None, purged:None, replication:{None}, heartbeat:{None}}
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}:flush_metrics:report_metrics:current_leader: openraft::core::raft_core: .../openraft/src/core/raft_core.rs:698: get current_leader self_id=NID[1] vote=<T3-NNID[0]:Q>
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}:flush_metrics:report_metrics:current_leader: openraft::core::raft_core: .../openraft/src/core/raft_core.rs:718: id=NID[0] is not a voter
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}:flush_metrics:report_metrics: openraft::core::raft_core: .../openraft/src/core/raft_core.rs:628: report_metrics: Metrics{id:NID[1], Follower, term:3, vote:<T3-NNID[0]:Q>, last_log:7, last_applied:None, leader:None(quorum_acked_time:None), membership:{log_id:0.0, {voters:[{NID[1]:NodeId[::b:0:0:0:16]}], learners:[]}}, snapshot:None, purged:None, replication:{None}, heartbeat:{None}}
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}: openraft::core::raft_core: .../openraft/src/core/raft_core.rs:913: RAFT_stats id=NID[1] log_io: flushed/submitted:((by:<T3-NNID[0]:Q>, None), (by:<T3-NNID[0]:Q>, None)], accepted: (by:<T3-NNID[0]:Q>, None)
DATE TRACE watch_state_change: raft_replication::raft_driver: src/raft/raft_replication/src/raft_driver.rs:163: Raft state event: RaftServerMetrics { id: NodeIndex(1), vote: Vote { leader_id: LeaderId { term: 3, voted_for: Some(NodeIndex(0)) }, committed: true }, state: Follower, current_leader: None, membership_config: StoredMembership { log_id: Some(LogId { leader_id: CommittedLeaderId { term: 0, p: PhantomData<raft_types::NodeIndex> }, index: 0 }), membership: Membership { configs: [{NodeIndex(1)}], nodes: {NodeIndex(1): NodeId[::b:0:0:0:16]} } } }
...
DATE  INFO RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}:handle_notification{state=Follower id=NID[1]}:handle_tick_election:elect: openraft::engine::engine_impl: .../openraft/src/engine/engine_impl.rs:217: openraft::engine::engine_impl::Engine<_>::elect, new candidate: {<T4-NNID[1]:->@14:46:17.394611, last_log_id:3.7 progress:{NID[1]: false}}
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}:handle_notification{state=Follower id=NID[1]}:handle_tick_election:elect:update_vote: openraft::engine::handler::vote_handler: .../openraft/src/engine/handler/vote_handler/mod.rs:111: vote is changing to vote=<T4-NNID[1]:->
... (voting with itself)
DATE  INFO RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}:handle_notification{state=Candidate id=NID[1]}:handle_vote_resp{target=NodeIndex(1)}: openraft::engine::engine_impl: .../openraft/src/engine/engine_impl.rs:348: a quorum granted my vote
DATE  INFO RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}:handle_notification{state=Candidate id=NID[1]}:handle_vote_resp{target=NodeIndex(1)}:establish_leader: openraft::engine::engine_impl: .../openraft/src/engine/engine_impl.rs:632: openraft::engine::engine_impl::Engine<_>::establish_leader
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}:handle_notification{state=Candidate id=NID[1]}:handle_vote_resp{target=NodeIndex(1)}:establish_leader:leader_append_entries: openraft::raft_state: .../openraft/src/raft_state/mod.rs:227: openraft::raft_state::RaftState<_>::accept_io: accept_log: current: (by:<T4-NNID[1]:Q>, 3.7), new_accepted: (by:<T4-NNID[1]:Q>, 4.8)
...
DATE DEBUG openraft::storage::callback: .../openraft/src/storage/callback.rs:69: openraft::storage::callback::IOFlushed<_>::io_completed: IOFlushed completed: IOFlushed: (by:<T4-NNID[1]:Q>, 4.8)
...
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}:handle_notification{state=Leader id=NID[1]}: openraft::engine::handler::replication_handler: .../openraft/src/engine/handler/replication_handler/mod.rs:355: openraft::engine::handler::replication_handler::ReplicationHandler<_>::update_local_progress upto=4.8
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}:handle_notification{state=Leader id=NID[1]}: openraft::engine::handler::replication_handler: .../openraft/src/engine/handler/replication_handler/mod.rs:365: update progress self_matching=3.7
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}:handle_notification{state=Leader id=NID[1]}:update_matching: openraft::engine::handler::replication_handler: .../openraft/src/engine/handler/replication_handler/mod.rs:150: openraft::engine::handler::replication_handler::ReplicationHandler<_>::update_matching node_id=NID[1] log_id=4.8
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}:handle_notification{state=Leader id=NID[1]}:update_matching: openraft::progress::entry: .../openraft/src/progress/entry/mod.rs:81: update_matching self={[3.7, 8), inflight:Logs:(None, 4.8]} matching=4.8
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}:handle_notification{state=Leader id=NID[1]}:update_matching: openraft::engine::handler::replication_handler: .../openraft/src/engine/handler/replication_handler/mod.rs:167: after updating progress quorum_accepted=4.8
...
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}:run_engine_commands:apply_to_state_machine: openraft::core::raft_core: .../openraft/src/core/raft_core.rs:749: openraft::core::raft_core::RaftCore<_, _, _>::apply_to_state_machine: 0.0..=4.8
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}:run_engine_commands:apply_to_state_machine: openraft::core::sm::handle: .../openraft/src/core/sm/handle.rs:28: sending command to state machine worker: Apply: [0.0,4.8]

afterwards, logs are applied and after we get metrics update that applied == committed, the regular operations continue and the test will find the persistent data.

After correcting the vote storage, the single-node is immediately deemed leader (which is correct), but doesn't apply logs or update committed index:

DATE  INFO RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:startup: openraft::engine::engine_impl: .../openraft/src/engine/engine_impl.rs:144: startup begin: state: RaftState { vote: Leased { data: Vote { leader_id: LeaderId { term: 3, voted_for: Some(NodeIndex(1)) }, committed: true }, last_update: Some(Instant(Instant { tv_sec: 858853, tv_nsec: 887660875 })), lease: 0ns, lease_enabled: true }, committed: None, purged_next: 0, log_ids: LogIdList { key_log_ids: [LogId { leader_id: CommittedLeaderId { term: 0, p: PhantomData<raft_types::NodeIndex> }, index: 0 }, LogId { leader_id: CommittedLeaderId { term: 3, p: PhantomData<raft_types::NodeIndex> }, index: 1 }, LogId { leader_id: CommittedLeaderId { term: 3, p: PhantomData<raft_types::NodeIndex> }, index: 7 }] }, membership_state: MembershipState { committed: EffectiveMembership { log_id: Some(LogId { leader_id: CommittedLeaderId { term: 0, p: PhantomData<raft_types::NodeIndex> }, index: 0 }), membership: Membership { configs: [{NodeIndex(1)}], nodes: {NodeIndex(1): NodeId[::b:0:0:0:16]} }, voter_ids: {NodeIndex(1)} }, effective: EffectiveMembership { log_id: Some(LogId { leader_id: CommittedLeaderId { term: 0, p: PhantomData<raft_types::NodeIndex> }, index: 0 }), membership: Membership { configs: [{NodeIndex(1)}], nodes: {NodeIndex(1): NodeId[::b:0:0:0:16]} }, voter_ids: {NodeIndex(1)} } }, snapshot_meta: SnapshotMeta { last_log_id: None, last_membership: StoredMembership { log_id: None, membership: Membership { configs: [], nodes: {} } }, snapshot_id: "" }, server_state: Learner, io_state: IOState { building_snapshot: false, io_progress: IOProgress { accepted: Some(Log(LogIOId { committed_vote: CommittedVote { vote: Vote { leader_id: LeaderId { term: 3, voted_for: Some(NodeIndex(1)) }, committed: true } }, log_id: None })), submitted: Some(Log(LogIOId { committed_vote: CommittedVote { vote: Vote { leader_id: LeaderId { term: 3, voted_for: Some(NodeIndex(1)) }, committed: true } }, log_id: None })), flushed: Some(Log(LogIOId { committed_vote: CommittedVote { vote: Vote { leader_id: LeaderId { term: 3, voted_for: Some(NodeIndex(1)) }, committed: true } }, log_id: None })) }, applied: None, snapshot: None, purged: None }, purge_upto: None }, is_leader: true, is_voter: true
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:startup: openraft::engine::handler::vote_handler: .../openraft/src/engine/handler/vote_handler/mod.rs:160: become leader: node-NID[1], my vote: <T3-NNID[1]:Q>, last-log-id: 3.7
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:startup: openraft::raft_state: .../openraft/src/raft_state/mod.rs:227: openraft::raft_state::RaftState<_>::accept_io: accept_log: current: (by:<T3-NNID[1]:Q>, None), new_accepted: (by:<T3-NNID[1]:Q>, 3.7)
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:startup: openraft::raft_state::io_state::io_progress: .../openraft/src/raft_state/io_state/io_progress.rs:89: RAFT_io_progress: flushed/submitted:((by:<T3-NNID[1]:Q>, None), (by:<T3-NNID[1]:Q>, None)], accepted: (by:<T3-NNID[1]:Q>, 3.7)
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:startup:calc_server_state: openraft::raft_state: .../openraft/src/raft_state/mod.rs:333: states contains=true is_voter=true is_leader=true is_leading=true
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:startup: openraft::engine::handler::server_state_handler: .../openraft/src/engine/handler/server_state_handler/mod.rs:25: update_server_state_if_changed id=NID[1] prev_server_state=Learner server_state=Leader
DATE  INFO RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:startup: openraft::engine::handler::server_state_handler: .../openraft/src/engine/handler/server_state_handler/mod.rs:40: become leader id=NID[1]
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:startup:rebuild_replication_streams: openraft::engine::engine_output: .../openraft/src/engine/engine_output.rs:30: push command: RebuildReplicationStreams { targets: [] }
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:startup:initiate_replication: openraft::engine::handler::replication_handler: .../openraft/src/engine/handler/replication_handler/mod.rs:274: openraft::engine::handler::replication_handler::ReplicationHandler<_>::initiate_replication progress=VecProgress { quorum_set: Joint { data: [[NodeIndex(1)]], _p: PhantomData<(raft_types::NodeIndex, alloc::vec::Vec<raft_types::NodeIndex>)> }, granted: Some(LogId { leader_id: CommittedLeaderId { term: 3, p: PhantomData<raft_types::NodeIndex> }, index: 7 }), voter_count: 1, vector: [(NodeIndex(1), ProgressEntry { matching: Some(LogId { leader_id: CommittedLeaderId { term: 3, p: PhantomData<raft_types::NodeIndex> }, index: 7 }), inflight: None, searching_end: 8 })], stat: Stat { update_count: 1, move_count: 1, is_quorum_count: 1 } }
...
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:report_metrics: openraft::core::raft_core: .../openraft/src/core/raft_core.rs:628: report_metrics: Metrics{id:NID[1], Leader, term:3, vote:<T3-NNID[1]:Q>, last_log:7, last_applied:None, leader:NID[1](quorum_acked_time:14:10:48.652176, 676.833µs ago), membership:{log_id:0.0, {voters:[{NID[1]:NodeId[::b:0:0:0:16]}], learners:[]}}, snapshot:None, purged:None, replication:{None}, heartbeat:{None}}
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}:flush_metrics:report_metrics: openraft::proposer::leader: .../openraft/src/proposer/leader.rs:211: openraft::proposer::leader::Leader<_, _>::last_quorum_acked_time: update with leader's local time, before retrieving quorum acked clock leader_id=NID[1] now=14:10:48.654462
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}:flush_metrics:report_metrics:current_leader: openraft::core::raft_core: .../openraft/src/core/raft_core.rs:698: get current_leader self_id=NID[1] vote=<T3-NNID[1]:Q>
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}:flush_metrics:report_metrics: openraft::core::raft_core: .../openraft/src/core/raft_core.rs:628: report_metrics: Metrics{id:NID[1], Leader, term:3, vote:<T3-NNID[1]:Q>, last_log:7, last_applied:None, leader:NID[1](quorum_acked_time:14:10:48.654462, 2.140458ms ago), membership:{log_id:0.0, {voters:[{NID[1]:NodeId[::b:0:0:0:16]}], learners:[]}}, snapshot:None, purged:None, replication:{NID[1]:3.7}, heartbeat:{NID[1]:14:10:48.652176}}
DATE DEBUG RaftCore{id=NID[1] cluster=...}:main:do_main{id=NID[1] cluster=...}:runtime_loop{id=NID[1]}: openraft::core::raft_core: .../openraft/src/core/raft_core.rs:913: RAFT_stats id=NID[1] log_io: flushed/submitted:((by:<T3-NNID[1]:Q>, None), (by:<T3-NNID[1]:Q>, None)], accepted: (by:<T3-NNID[1]:Q>, 3.7)
DATE TRACE watch_state_change: raft_replication::raft_driver: src/raft/raft_replication/src/raft_driver.rs:163: Raft state event: RaftServerMetrics { id: NodeIndex(1), vote: Vote { leader_id: LeaderId { term: 3, voted_for: Some(NodeIndex(1)) }, committed: true }, state: Leader, current_leader: Some(NodeIndex(1)), membership_config: StoredMembership { log_id: Some(LogId { leader_id: CommittedLeaderId { term: 0, p: PhantomData<raft_types::NodeIndex> }, index: 0 }), membership: Membership { configs: [{NodeIndex(1)}], nodes: {NodeIndex(1): NodeId[::b:0:0:0:16]} } } }
...

No Apply command is sent. Although openraft continues running in the background and "ticks", the missing previously committed entries are not applied.

[github-actions]

👋 Thanks for opening this issue!

Get help or engage by:

• /help : to print help messages.
• /assignme : to assign this issue to you.

[drmingdrmer]

It appears to be a bug with Openraft. As you mentioned, the committed log ID is not updated when the node is brought up as a sole leader.

Currently, the committed log ID is updated in two scenarios during node startup: either by synchronization from an existing leader or when the node itself becomes leadership and appends a new blank log entry.

Let me fix it!

[drmingdrmer]

@schreter Please help me to confirm the issue is addressed with the latest main branch: 681d04d

Feel free re-open this issue if there is anything wrong :)

[schreter]

@drmingdrmer Yes, with the update, the affected test case runs as expected :-).

Thanks for a quick fix.