Abhishek Chennaka created KUDU-3762:
---------------------------------------
Summary: 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
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 maste 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}
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.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
