[
https://issues.apache.org/jira/browse/KUDU-3762?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Abhishek Chennaka resolved KUDU-3762.
-------------------------------------
Fix Version/s: 1.19.0
Resolution: Fixed
> 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
> Fix For: 1.19.0
>
>
> 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)
