[
https://issues.apache.org/jira/browse/IGNITE-20996?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Kirill Gusakov updated IGNITE-20996:
------------------------------------
Description:
The successful rebalance happens after successful raft configuration change and
invoke to meta storage with replacing stable assignments with pending ones.
Also there is the following line in the log:
{code:java}
[2023-11-30T09:20:25,028][INFO
][%iinrt_tcg_0%rebalance-scheduler-1][RebalanceRaftGroupEventsListener]
Rebalance finished [tablePartitionId=9_part_1, appliedPeers=[Assignment
[consistentId=iinrt_tcg_0, isPeer=true], Assignment [consistentId=iinrt_tcg_1,
isPeer=true], Assignment [consistentId=iinrt_tcg_2, isPeer=true], Assignment
[consistentId=iinrt_tcg_3, isPeer=true]]]{code}
But in case when there were errors on FSM on replication, the result of the
rebalance looks the same, in spite the data was not actually replicated.
Probably there are some problems in raft that allow triggering the
configuration change event in spite of errors in state machine.
*Update*:
The issue can be reproduced as:
- Unmute testCfgGap test
- Change NodeOptions.catchupMargin to any value smaller than 100 (because
actually this tests write and check the replication of 100 rows)
- Run the test
Expected result:
- Catchup phas of rebalance failed
Actual result:
{code}
[2023-12-08T17:24:41,738][INFO
][%iinrt_tcg_1%JRaft-Common-Executor-2][NodeImpl] Catch up for peer=iinrt_tcg_3
was finished
[2023-12-08T17:24:41,739][INFO
][%iinrt_tcg_1%JRaft-Common-Executor-2][NodeImpl] Catch up phase to change
peers from=[iinrt_tcg_2, iinrt_tcg_1, iinrt_tcg_0] to=[iinrt_tcg_3,
iinrt_tcg_0, iinrt_tcg_1, iinrt_tcg_2] was successfully finished
[2023-12-08T17:24:41,743][INFO
][%iinrt_tcg_1%JRaft-FSMCaller-Disruptor-_stripe_5-0][StateMachineAdapter]
onConfigurationCommitted: iinrt_tcg_3,iinrt_tcg_0,iinrt_tcg_1,iinrt_tcg_2.
[2023-12-08T17:24:41,744][INFO
][%iinrt_tcg_2%JRaft-FSMCaller-Disruptor-_stripe_4-0][StateMachineAdapter]
onConfigurationCommitted: iinrt_tcg_3,iinrt_tcg_0,iinrt_tcg_1,iinrt_tcg_2.
[2023-12-08T17:24:41,744][INFO
][%iinrt_tcg_0%JRaft-FSMCaller-Disruptor-_stripe_6-0][StateMachineAdapter]
onConfigurationCommitted: iinrt_tcg_3,iinrt_tcg_0,iinrt_tcg_1,iinrt_tcg_2.
[2023-12-08T17:24:41,745][WARN
][%iinrt_tcg_1%JRaft-Common-Executor-1][RpcRequestClosure] A response:
ChangePeersAsyncResponseImpl [newLearnersList=ArrayList [],
newPeersList=ArrayList [iinrt_tcg_3, iinrt_tcg_0, iinrt_tcg_1, iinrt_tcg_2],
oldLearnersList=ArrayList [], oldPeersList=ArrayList [iinrt_tcg_2, iinrt_tcg_1,
iinrt_tcg_0]] sent repeatedly!
[2023-12-08T17:24:41,745][ERROR][%iinrt_tcg_3%JRaft-FSMCaller-Disruptor-_stripe_3-0][PartitionListener]
Unknown error while processing command [commandIndex=2, commandTerm=2,
command=UpdateAllCommandImpl [full=false, messageRowsToUpdate=HashMap
{1ed55656-1c13-4382-b4d2-c68c2106bef7=TimedBinaryRowMessageImpl
[binaryRowMessage=BinaryRowMessageImpl
[binaryTuple=java.nio.HeapByteBuffer[pos=0 lim=9 cap=9], schemaVersion=1],
timestamp=0]}, requiredCatalogVersion=5, safeTimeLong=111545252503945221,
tablePartitionId=TablePartitionIdMessageImpl [partitionId=0, tableId=9],
txCoordinatorId=aecb6e7e-4b5c-41b4-aaa5-17b8568c67b1,
txId=018c49d0-e9fc-0000-0000-0000dc9ad69a]]
java.lang.AssertionError: T2 part 0
at
org.apache.ignite.internal.table.IndexWrapper$HashIndexWrapper.getStorage(IndexWrapper.java:106)
~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.table.TableImpl$1.get(TableImpl.java:211)
~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.internal.table.distributed.index.IndexUpdateHandler.waitIndexes(IndexUpdateHandler.java:151)
~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.internal.table.distributed.StorageUpdateHandler.handleUpdateAll(StorageUpdateHandler.java:158)
~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.internal.table.distributed.raft.PartitionListener.handleUpdateAllCommand(PartitionListener.java:293)
~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.internal.table.distributed.raft.PartitionListener.lambda$onWrite$1(PartitionListener.java:199)
~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at java.util.Iterator.forEachRemaining(Iterator.java:133) [?:?]
at
org.apache.ignite.internal.table.distributed.raft.PartitionListener.onWrite(PartitionListener.java:159)
[ignite-table-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.internal.raft.server.impl.JraftServerImpl$DelegatingStateMachine.onApply(JraftServerImpl.java:659)
[ignite-raft-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.raft.jraft.core.FSMCallerImpl.doApplyTasks(FSMCallerImpl.java:557)
[ignite-raft-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.raft.jraft.core.FSMCallerImpl.doCommitted(FSMCallerImpl.java:525)
[ignite-raft-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.raft.jraft.core.FSMCallerImpl.runApplyTask(FSMCallerImpl.java:444)
[ignite-raft-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.raft.jraft.core.FSMCallerImpl$ApplyTaskHandler.onEvent(FSMCallerImpl.java:136)
[ignite-raft-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.raft.jraft.core.FSMCallerImpl$ApplyTaskHandler.onEvent(FSMCallerImpl.java:130)
[ignite-raft-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.raft.jraft.disruptor.StripedDisruptor$StripeEntryHandler.onEvent(StripedDisruptor.java:226)
[ignite-raft-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.raft.jraft.disruptor.StripedDisruptor$StripeEntryHandler.onEvent(StripedDisruptor.java:191)
[ignite-raft-3.0.0-SNAPSHOT.jar:?]
at
com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:137)
[disruptor-3.3.7.jar:?]
at java.lang.Thread.run(Thread.java:834) [?:?]
{code}
So, according to the logs we can't replicate even the first message to the new
node, but the catchup phase is done successfully. *That's the main problem,
which should be investigated*. What about rebalance itself - it can be finished
successfully anyway, because majority of the nodes (3/4) is applied
configuration entry successfully.
Also, the test itself is green, but it shouldn't. The last check
{code}
checkTableWithData(newNode, "t2");
{code}
supposed to check the data replication to the newNode (so, it can't be
successfull), but it looks like it checks the data on primary replica instead.
So, test must be updated to the real 1-node data check after the fix
https://issues.apache.org/jira/browse/IGNITE-19712
was:
The successful rebalance happens after successful raft configuration change and
invoke to meta storage with replacing stable assignments with pending ones.
Also there is the following line in the log:
{code:java}
[2023-11-30T09:20:25,028][INFO
][%iinrt_tcg_0%rebalance-scheduler-1][RebalanceRaftGroupEventsListener]
Rebalance finished [tablePartitionId=9_part_1, appliedPeers=[Assignment
[consistentId=iinrt_tcg_0, isPeer=true], Assignment [consistentId=iinrt_tcg_1,
isPeer=true], Assignment [consistentId=iinrt_tcg_2, isPeer=true], Assignment
[consistentId=iinrt_tcg_3, isPeer=true]]]{code}
But in case when there were errors on FSM on replication, the result of the
rebalance looks the same, in spite the data was not actually replicated.
Probably there are some problems in raft that allow triggering the
configuration change event in spite of errors in state machine.
> Rebalance can be considered as successful while actual data replication failed
> ------------------------------------------------------------------------------
>
> Key: IGNITE-20996
> URL: https://issues.apache.org/jira/browse/IGNITE-20996
> Project: Ignite
> Issue Type: Bug
> Reporter: Denis Chudov
> Priority: Major
> Labels: ignite-3
>
> The successful rebalance happens after successful raft configuration change
> and invoke to meta storage with replacing stable assignments with pending
> ones. Also there is the following line in the log:
>
> {code:java}
> [2023-11-30T09:20:25,028][INFO
> ][%iinrt_tcg_0%rebalance-scheduler-1][RebalanceRaftGroupEventsListener]
> Rebalance finished [tablePartitionId=9_part_1, appliedPeers=[Assignment
> [consistentId=iinrt_tcg_0, isPeer=true], Assignment
> [consistentId=iinrt_tcg_1, isPeer=true], Assignment
> [consistentId=iinrt_tcg_2, isPeer=true], Assignment
> [consistentId=iinrt_tcg_3, isPeer=true]]]{code}
>
> But in case when there were errors on FSM on replication, the result of the
> rebalance looks the same, in spite the data was not actually replicated.
> Probably there are some problems in raft that allow triggering the
> configuration change event in spite of errors in state machine.
> *Update*:
> The issue can be reproduced as:
> - Unmute testCfgGap test
> - Change NodeOptions.catchupMargin to any value smaller than 100 (because
> actually this tests write and check the replication of 100 rows)
> - Run the test
> Expected result:
> - Catchup phas of rebalance failed
> Actual result:
> {code}
> [2023-12-08T17:24:41,738][INFO
> ][%iinrt_tcg_1%JRaft-Common-Executor-2][NodeImpl] Catch up for
> peer=iinrt_tcg_3 was finished
> [2023-12-08T17:24:41,739][INFO
> ][%iinrt_tcg_1%JRaft-Common-Executor-2][NodeImpl] Catch up phase to change
> peers from=[iinrt_tcg_2, iinrt_tcg_1, iinrt_tcg_0] to=[iinrt_tcg_3,
> iinrt_tcg_0, iinrt_tcg_1, iinrt_tcg_2] was successfully finished
> [2023-12-08T17:24:41,743][INFO
> ][%iinrt_tcg_1%JRaft-FSMCaller-Disruptor-_stripe_5-0][StateMachineAdapter]
> onConfigurationCommitted: iinrt_tcg_3,iinrt_tcg_0,iinrt_tcg_1,iinrt_tcg_2.
> [2023-12-08T17:24:41,744][INFO
> ][%iinrt_tcg_2%JRaft-FSMCaller-Disruptor-_stripe_4-0][StateMachineAdapter]
> onConfigurationCommitted: iinrt_tcg_3,iinrt_tcg_0,iinrt_tcg_1,iinrt_tcg_2.
> [2023-12-08T17:24:41,744][INFO
> ][%iinrt_tcg_0%JRaft-FSMCaller-Disruptor-_stripe_6-0][StateMachineAdapter]
> onConfigurationCommitted: iinrt_tcg_3,iinrt_tcg_0,iinrt_tcg_1,iinrt_tcg_2.
> [2023-12-08T17:24:41,745][WARN
> ][%iinrt_tcg_1%JRaft-Common-Executor-1][RpcRequestClosure] A response:
> ChangePeersAsyncResponseImpl [newLearnersList=ArrayList [],
> newPeersList=ArrayList [iinrt_tcg_3, iinrt_tcg_0, iinrt_tcg_1, iinrt_tcg_2],
> oldLearnersList=ArrayList [], oldPeersList=ArrayList [iinrt_tcg_2,
> iinrt_tcg_1, iinrt_tcg_0]] sent repeatedly!
> [2023-12-08T17:24:41,745][ERROR][%iinrt_tcg_3%JRaft-FSMCaller-Disruptor-_stripe_3-0][PartitionListener]
> Unknown error while processing command [commandIndex=2, commandTerm=2,
> command=UpdateAllCommandImpl [full=false, messageRowsToUpdate=HashMap
> {1ed55656-1c13-4382-b4d2-c68c2106bef7=TimedBinaryRowMessageImpl
> [binaryRowMessage=BinaryRowMessageImpl
> [binaryTuple=java.nio.HeapByteBuffer[pos=0 lim=9 cap=9], schemaVersion=1],
> timestamp=0]}, requiredCatalogVersion=5, safeTimeLong=111545252503945221,
> tablePartitionId=TablePartitionIdMessageImpl [partitionId=0, tableId=9],
> txCoordinatorId=aecb6e7e-4b5c-41b4-aaa5-17b8568c67b1,
> txId=018c49d0-e9fc-0000-0000-0000dc9ad69a]]
> java.lang.AssertionError: T2 part 0
> at
> org.apache.ignite.internal.table.IndexWrapper$HashIndexWrapper.getStorage(IndexWrapper.java:106)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.table.TableImpl$1.get(TableImpl.java:211)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at
> org.apache.ignite.internal.table.distributed.index.IndexUpdateHandler.waitIndexes(IndexUpdateHandler.java:151)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at
> org.apache.ignite.internal.table.distributed.StorageUpdateHandler.handleUpdateAll(StorageUpdateHandler.java:158)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at
> org.apache.ignite.internal.table.distributed.raft.PartitionListener.handleUpdateAllCommand(PartitionListener.java:293)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at
> org.apache.ignite.internal.table.distributed.raft.PartitionListener.lambda$onWrite$1(PartitionListener.java:199)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at java.util.Iterator.forEachRemaining(Iterator.java:133) [?:?]
> at
> org.apache.ignite.internal.table.distributed.raft.PartitionListener.onWrite(PartitionListener.java:159)
> [ignite-table-3.0.0-SNAPSHOT.jar:?]
> at
> org.apache.ignite.internal.raft.server.impl.JraftServerImpl$DelegatingStateMachine.onApply(JraftServerImpl.java:659)
> [ignite-raft-3.0.0-SNAPSHOT.jar:?]
> at
> org.apache.ignite.raft.jraft.core.FSMCallerImpl.doApplyTasks(FSMCallerImpl.java:557)
> [ignite-raft-3.0.0-SNAPSHOT.jar:?]
> at
> org.apache.ignite.raft.jraft.core.FSMCallerImpl.doCommitted(FSMCallerImpl.java:525)
> [ignite-raft-3.0.0-SNAPSHOT.jar:?]
> at
> org.apache.ignite.raft.jraft.core.FSMCallerImpl.runApplyTask(FSMCallerImpl.java:444)
> [ignite-raft-3.0.0-SNAPSHOT.jar:?]
> at
> org.apache.ignite.raft.jraft.core.FSMCallerImpl$ApplyTaskHandler.onEvent(FSMCallerImpl.java:136)
> [ignite-raft-3.0.0-SNAPSHOT.jar:?]
> at
> org.apache.ignite.raft.jraft.core.FSMCallerImpl$ApplyTaskHandler.onEvent(FSMCallerImpl.java:130)
> [ignite-raft-3.0.0-SNAPSHOT.jar:?]
> at
> org.apache.ignite.raft.jraft.disruptor.StripedDisruptor$StripeEntryHandler.onEvent(StripedDisruptor.java:226)
> [ignite-raft-3.0.0-SNAPSHOT.jar:?]
> at
> org.apache.ignite.raft.jraft.disruptor.StripedDisruptor$StripeEntryHandler.onEvent(StripedDisruptor.java:191)
> [ignite-raft-3.0.0-SNAPSHOT.jar:?]
> at
> com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:137)
> [disruptor-3.3.7.jar:?]
> at java.lang.Thread.run(Thread.java:834) [?:?]
> {code}
> So, according to the logs we can't replicate even the first message to the
> new node, but the catchup phase is done successfully. *That's the main
> problem, which should be investigated*. What about rebalance itself - it can
> be finished successfully anyway, because majority of the nodes (3/4) is
> applied configuration entry successfully.
> Also, the test itself is green, but it shouldn't. The last check
> {code}
> checkTableWithData(newNode, "t2");
> {code}
> supposed to check the data replication to the newNode (so, it can't be
> successfull), but it looks like it checks the data on primary replica
> instead. So, test must be updated to the real 1-node data check after the fix
> https://issues.apache.org/jira/browse/IGNITE-19712
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
