[
https://issues.apache.org/jira/browse/KUDU-3762?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18081443#comment-18081443
]
ASF subversion and git services commented on KUDU-3762:
-------------------------------------------------------
Commit 66827b15b158c37363c37baa160f29a0ca1f1e63 in kudu's branch
refs/heads/master from Abhishek Chennaka
[ https://gitbox.apache.org/repos/asf?p=kudu.git;h=66827b15b ]
KUDU-3762 - Fix catchup deadlock on LMP mismatch
A Raft leader could enter an infinite LMP mismatch loop if it erroneously
marked a peer as unrecoverable (wal_catchup_possible = false). In this
state, RequestForPeer() skips log-position negotiation and sends status
updates at the log tip. If the peer is behind, it rejects the request,
triggering an immediate retry loop that consumes CPU and prevents catchup.
This patch introduces is_joining_existing_cluster_ in CatalogManager to
silence heartbeats and background tasks during the join phase. Explicitly
shuts down the system catalog tablet before initiating AddMaster() to
prevent the leader from seeing a stale Index 0 state.
Testing:
- Added a test case to reproduce the issue.
- Verified the fix resolves the loop and allows the new master to become
a voter.
Change-Id: I00f4f840c21cc037a2aa6c023af168352fef0761
Reviewed-on: http://gerrit.cloudera.org:8080/24287
Reviewed-by: Alexey Serbin <[email protected]>
Tested-by: Abhishek Chennaka <[email protected]>
> New Kudu master unable to catchup after being added
> ---------------------------------------------------
>
> Key: KUDU-3762
> URL: https://issues.apache.org/jira/browse/KUDU-3762
> Project: Kudu
> Issue Type: Bug
> Reporter: Abhishek Chennaka
> Assignee: Abhishek Chennaka
> Priority: Major
>
> If a new/blank Kudu master is run providing the address of an existing Kudu
> master, it registers itself with the new Kudu master and copies over the
> system catalog from the existing master.
> After this copy is done and before the tablet starts running in the new
> master, if there are additional entries in the existing leader master's WAL
> segment, basically if the committed index advances even by one operation, the
> new master is unable to catchup even if the WAL segment(/s) containing these
> operations are not GC'd.
> With additional logging enabled I see the below pattern of logs in the old
> master:
> {code:java}
> I20260409 21:57:50.110136 659402 consensus_peers.cc:287] T
> 00000000000000000000000000000000 P 8ca90398fc3045e0a088805d214621e3 -> Peer
> 89c9e8be413345a881516dee793c82e2 (achennaka-kudu1-2.vpc.cloudera.com:7051):
> Sendi
> ng to peer 89c9e8be413345a881516dee793c82e2: tablet_id:
> "00000000000000000000000000000000" caller_uuid:
> "8ca90398fc3045e0a088805d214621e3" caller_term: 13 preceding_id { term: 13
> index: 36910 } dest_uuid: "89c9e8be41
> 3345a881516dee793c82e2" committed_index: 36910 all_replicated_index: 0
> safe_timestamp: 7273664799164919808 last_idx_appended_to_leader: 36910
> I20260409 21:57:50.110736 659402 consensus_peers.cc:412] T
> 00000000000000000000000000000000 P 8ca90398fc3045e0a088805d214621e3 -> Peer
> 89c9e8be413345a881516dee793c82e2 (achennaka-kudu1-2.vpc.cloudera.com:7051):
> Respo
> nse from peer 89c9e8be413345a881516dee793c82e2: responder_uuid:
> "89c9e8be413345a881516dee793c82e2" responder_term: 13 status { last_received
> { term: 13 index: 28782 } last_committed_idx: 28782 error { code: PRECEDING
> _ENTRY_DIDNT_MATCH status { code: ILLEGAL_STATE message: "Log matching
> property violated. Preceding OpId in replica: term: 13 index: 28782.
> Preceding OpId from leader: term: 13 index: 36910. (index mismatch)" } } las
> t_received_current_leader { term: 0 index: 0 } }
> I20260409 21:57:50.110798 659402 consensus_queue.cc:1035] T
> 00000000000000000000000000000000 P 8ca90398fc3045e0a088805d214621e3 [LEADER]:
> Got LMP mismatch error from peer: Peer: permanent_uuid: "89c9e8be413345a881516
> dee793c82e2" member_type: NON_VOTER last_known_addr { host:
> "achennaka-kudu1-2.vpc.cloudera.com" port: 7051 } attrs { promote: true },
> Status: LMP_MISMATCH, Last received: 13.28782, Next index: 28783, Last known
> comm
> itted idx: 28782, Time since last communication: 0.000s
> I20260409 21:57:50.110872 659402 hybrid_clock.cc:452] Current clock is higher
> than the last one. Resetting logical values. Physical Value: 1775797070109428
> usec Logical Value: 0 Error: 46778
> I20260409 21:57:50.110909 659402 consensus_queue.cc:809] T
> 00000000000000000000000000000000 P 8ca90398fc3045e0a088805d214621e3 [LEADER]:
> Sending status only request to Peer: 89c9e8be413345a881516dee793c82e2:
> tablet_i
> d: "00000000000000000000000000000000"
> caller_uuid: "8ca90398fc3045e0a088805d214621e3"
> caller_term: 13
> preceding_id {
> term: 13
> index: 36910
> }
> dest_uuid: "89c9e8be413345a881516dee793c82e2"
> committed_index: 36910
> all_replicated_index: 0
> safe_timestamp: 7273664799168217088
> last_idx_appended_to_leader: 36910
> I20260409 21:57:50.110954 659402 consensus_peers.cc:287] T
> 00000000000000000000000000000000 P 8ca90398fc3045e0a088805d214621e3 -> Peer
> 89c9e8be413345a881516dee793c82e2 (achennaka-kudu1-2.vpc.cloudera.com:7051):
> Sendi
> ng to peer 89c9e8be413345a881516dee793c82e2: tablet_id:
> "00000000000000000000000000000000" caller_uuid:
> "8ca90398fc3045e0a088805d214621e3" caller_term: 13 preceding_id { term: 13
> index: 36910 } dest_uuid: "89c9e8be41
> 3345a881516dee793c82e2" committed_index: 36910 all_replicated_index: 0
> safe_timestamp: 7273664799168217088 last_idx_appended_to_leader: 36910
> I20260409 21:57:50.111559 659402 consensus_peers.cc:412] T
> 00000000000000000000000000000000 P 8ca90398fc3045e0a088805d214621e3 -> Peer
> 89c9e8be413345a881516dee793c82e2 (achennaka-kudu1-2.vpc.cloudera.com:7051):
> Respo
> nse from peer 89c9e8be413345a881516dee793c82e2: responder_uuid:
> "89c9e8be413345a881516dee793c82e2" responder_term: 13 status { last_received
> { term: 13 index: 28782 } last_committed_idx: 28782 error { code: PRECEDING
> _ENTRY_DIDNT_MATCH status { code: ILLEGAL_STATE message: "Log matching
> property violated. Preceding OpId in replica: term: 13 index: 28782.
> Preceding OpId from leader: term: 13 index: 36910. (index mismatch)" } } las
> t_received_current_leader { term: 0 index: 0 } }
> I20260409 21:57:50.111626 659402 consensus_queue.cc:1035] T
> 00000000000000000000000000000000 P 8ca90398fc3045e0a088805d214621e3 [LEADER]:
> Got LMP mismatch error from peer: Peer: permanent_uuid: "89c9e8be413345a881516
> dee793c82e2" member_type: NON_VOTER last_known_addr { host:
> "achennaka-kudu1-2.vpc.cloudera.com" port: 7051 } attrs { promote: true },
> Status: LMP_MISMATCH, Last received: 13.28782, Next index: 28783, Last known
> comm
> itted idx: 28782, Time since last communication: 0.000s
> I20260409 21:57:50.111685 659402 hybrid_clock.cc:452] Current clock is higher
> than the last one. Resetting logical values. Physical Value: 1775797070110241
> usec Logical Value: 0 Error: 46778
> I20260409 21:57:50.111713 659402 consensus_queue.cc:809] T
> 00000000000000000000000000000000 P 8ca90398fc3045e0a088805d214621e3 [LEADER]:
> Sending status only request to Peer: 89c9e8be413345a881516dee793c82e2:
> tablet_i
> d: "00000000000000000000000000000000"
> caller_uuid: "8ca90398fc3045e0a088805d214621e3"
> caller_term: 13
> preceding_id {
> term: 13
> index: 36910
> }
> dest_uuid: "89c9e8be413345a881516dee793c82e2"
> committed_index: 36910
> all_replicated_index: 0
> safe_timestamp: 7273664799171547136
> last_idx_appended_to_leader: 36910
> I20260409 21:57:50.111752 659402 consensus_peers.cc:287] T
> 00000000000000000000000000000000 P 8ca90398fc3045e0a088805d214621e3 -> Peer
> 89c9e8be413345a881516dee793c82e2 (achennaka-kudu1-2.vpc.cloudera.com:7051):
> Sendi
> ng to peer 89c9e8be413345a881516dee793c82e2: tablet_id:
> "00000000000000000000000000000000" caller_uuid:
> "8ca90398fc3045e0a088805d214621e3" caller_term: 13 preceding_id { term: 13
> index: 36910 } dest_uuid: "89c9e8be41
> 3345a881516dee793c82e2" committed_index: 36910 all_replicated_index: 0
> safe_timestamp: 7273664799171547136 last_idx_appended_to_leader: 36910 {code}
> The new master log have the below patterns:
> {code:java}
> I20260409 21:57:50.109891 134046 raft_consensus.cc:1091] T
> 00000000000000000000000000000000 P 89c9e8be413345a881516dee793c82e2 [term 13
> LEARNER]: Replica replied to status only request. Replica: Replica:
> 89c9e8be413345a881516dee793c82e2, State: Running, Role: LEARNER. Response:
> responder_uuid: "89c9e8be413345a881516dee793c82e2" responder_term: 13 status
> { last_received { term: 13 index: 28782 } last_committed_idx: 28782 error {
> code: PRECEDING_ENTRY_DIDNT_MATCH status { code: ILLEGAL_STATE message: "Log
> matching property violated. Preceding OpId in replica: term: 13 index: 28782.
> Preceding OpId from leader: term: 13 index: 36910. (index mismatch)" } }
> last_received_current_leader { term: 0 index: 0 } }
> I20260409 21:57:50.110622 134046 raft_consensus.cc:1084] T
> 00000000000000000000000000000000 P 89c9e8be413345a881516dee793c82e2 [term 13
> LEARNER]: Replica received request: tablet_id:
> "00000000000000000000000000000000" caller_uuid:
> "8ca90398fc3045e0a088805d214621e3" caller_term: 13 preceding_id { term: 13
> index: 36910 } dest_uuid: "89c9e8be413345a881516dee793c82e2" committed_index:
> 36910 all_replicated_index: 0 safe_timestamp: 7273664799161720832
> last_idx_appended_to_leader: 36910
> I20260409 21:57:50.110684 134046 raft_consensus.cc:1261] T
> 00000000000000000000000000000000 P 89c9e8be413345a881516dee793c82e2 [term 13
> LEARNER]: Refusing update from remote peer 8ca90398fc3045e0a088805d214621e3:
> Log matching property violated. Preceding OpId in replica: term: 13 index:
> 28782. Preceding OpId from leader: term: 13 index: 36910. (index mismatch)
> I20260409 21:57:50.110700 134046 raft_consensus.cc:1091] T
> 00000000000000000000000000000000 P 89c9e8be413345a881516dee793c82e2 [term 13
> LEARNER]: Replica replied to status only request. Replica: Replica:
> 89c9e8be413345a881516dee793c82e2, State: Running, Role: LEARNER. Response:
> responder_uuid: "89c9e8be413345a881516dee793c82e2" responder_term: 13 status
> { last_received { term: 13 index: 28782 } last_committed_idx: 28782 error {
> code: PRECEDING_ENTRY_DIDNT_MATCH status { code: ILLEGAL_STATE message: "Log
> matching property violated. Preceding OpId in replica: term: 13 index: 28782.
> Preceding OpId from leader: term: 13 index: 36910. (index mismatch)" } }
> last_received_current_leader { term: 0 index: 0 } }
> I20260409 21:57:50.111368 134046 raft_consensus.cc:1084] T
> 00000000000000000000000000000000 P 89c9e8be413345a881516dee793c82e2 [term 13
> LEARNER]: Replica received request: tablet_id:
> "00000000000000000000000000000000" caller_uuid:
> "8ca90398fc3045e0a088805d214621e3" caller_term: 13 preceding_id { term: 13
> index: 36910 } dest_uuid: "89c9e8be413345a881516dee793c82e2" committed_index:
> 36910 all_replicated_index: 0 safe_timestamp: 7273664799164919808
> last_idx_appended_to_leader: 36910 {code}
> The new master will be stuck in LEARNER state and the old master will be the
> LEADER at this point.
> Steps to reproduce:
> 1. Ensure the existing leader has GC'd at least one log segment(This
> initiates the tablet data copy and not the WAL segment copy).
> 2. Ensure there are some table DDL operations running in background to
> advance configuration index in the write ahead log.
> 3. Start the new master.
> Workaround (to be performed when there will the Kudu cluster is idle):
> 1. Shutdown the new master and force delete the catalog form the new master:
> sudo -u kudu kudu local_replica delete 00000000000000000000000000000000
> -fs_data_dirs=<data_dirs> -fs_wal_dir=<wal_dir> -clean_unsafe=true
> 2. Copy over the system catalog:
> sudo -u kudu kudu local_replica copy_from_remote
> 00000000000000000000000000000000 <old_master>:7051 -fs_data_dirs=<data_dirs>
> -fs_wal_dir=<wal_dir>
> 3. Start back the new master
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
