[
https://issues.apache.org/jira/browse/KUDU-3762?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Abhishek Chennaka updated KUDU-3762:
------------------------------------
Description:
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}
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
was:
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.
> 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}
> 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)
