You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@ignite.apache.org by "Denis Chudov (Jira)" <ji...@apache.org> on 2024/07/22 12:18:00 UTC
[jira] [Comment Edited] (IGNITE-20996) Rebalance can be considered as successful while actual data replication failed
[ https://issues.apache.org/jira/browse/IGNITE-20996?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17867741#comment-17867741 ]
Denis Chudov edited comment on IGNITE-20996 at 7/22/24 12:17 PM:
-----------------------------------------------------------------
Reproducer no longer works after IGNITE-21501
Stack trace of the assertion occurred before
{code:java}
[2024-07-22T15:11:06,750][ERROR][%iinrt_tcg_3%JRaft-FSMCaller-Disruptor_stripe_1-0][PartitionListener] Unknown error while processing command [commandIndex=2, commandTerm=2, command=UpdateCommandImpl [full=false, messageRowToUpdate=TimedBinaryRowMessageImpl [binaryRowMessage=BinaryRowMessageImpl [binaryTuple=java.nio.HeapByteBuffer[pos=0 lim=9 cap=9], schemaVersion=1], timestamp=0], requiredCatalogVersion=5, rowUuid=12383f8a-8691-49d7-af6c-36787f99dff9, safeTimeLong=112830071591141377, tablePartitionId=TablePartitionIdMessageImpl [partitionId=1, tableId=11], txCoordinatorId=c08fd32b-cfef-4f11-b8cd-dad4ee3f7789, txId=0190da5a-312a-0003-dc9a-d69a00000001]]
java.lang.AssertionError: T2 part 1
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.lambda$indexStorageAdapters$0(TableImpl.java:239) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.table.distributed.index.IndexUpdateHandler.indexes(IndexUpdateHandler.java:179) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.table.distributed.index.IndexUpdateHandler.addToIndexes(IndexUpdateHandler.java:68) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.table.distributed.StorageUpdateHandler.tryProcessRow(StorageUpdateHandler.java:173) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.table.distributed.StorageUpdateHandler.lambda$handleUpdate$0(StorageUpdateHandler.java:114) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.storage.pagememory.mv.PersistentPageMemoryMvPartitionStorage.lambda$runConsistently$0(PersistentPageMemoryMvPartitionStorage.java:156) ~[ignite-storage-page-memory-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.storage.pagememory.mv.AbstractPageMemoryMvPartitionStorage.busy(AbstractPageMemoryMvPartitionStorage.java:759) ~[ignite-storage-page-memory-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.storage.pagememory.mv.PersistentPageMemoryMvPartitionStorage.runConsistently(PersistentPageMemoryMvPartitionStorage.java:146) ~[ignite-storage-page-memory-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.storage.ThreadAssertingMvPartitionStorage.runConsistently(ThreadAssertingMvPartitionStorage.java:48) ~[ignite-storage-api-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.table.distributed.raft.snapshot.outgoing.SnapshotAwarePartitionDataStorage.runConsistently(SnapshotAwarePartitionDataStorage.java:76) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.table.distributed.StorageUpdateHandler.handleUpdate(StorageUpdateHandler.java:109) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.table.distributed.raft.PartitionListener.handleUpdateCommand(PartitionListener.java:266) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.table.distributed.raft.PartitionListener.lambda$onWrite$1(PartitionListener.java:202) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at java.base/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:690) [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:266) [ignite-raft-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.raft.jraft.disruptor.StripedDisruptor$StripeEntryHandler.onEvent(StripedDisruptor.java:231) [ignite-raft-3.0.0-SNAPSHOT.jar:?]
at com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:167) [disruptor-4.0.0.jar:?]
at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:122) [disruptor-4.0.0.jar:?]
at java.base/java.lang.Thread.run(Thread.java:834) [?:?] {code}
was (Author: denis chudov):
Reproducer no longer works after
Stack trace of the assertion occurred before
{code:java}
[2024-07-22T15:11:06,750][ERROR][%iinrt_tcg_3%JRaft-FSMCaller-Disruptor_stripe_1-0][PartitionListener] Unknown error while processing command [commandIndex=2, commandTerm=2, command=UpdateCommandImpl [full=false, messageRowToUpdate=TimedBinaryRowMessageImpl [binaryRowMessage=BinaryRowMessageImpl [binaryTuple=java.nio.HeapByteBuffer[pos=0 lim=9 cap=9], schemaVersion=1], timestamp=0], requiredCatalogVersion=5, rowUuid=12383f8a-8691-49d7-af6c-36787f99dff9, safeTimeLong=112830071591141377, tablePartitionId=TablePartitionIdMessageImpl [partitionId=1, tableId=11], txCoordinatorId=c08fd32b-cfef-4f11-b8cd-dad4ee3f7789, txId=0190da5a-312a-0003-dc9a-d69a00000001]]
java.lang.AssertionError: T2 part 1
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.lambda$indexStorageAdapters$0(TableImpl.java:239) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.table.distributed.index.IndexUpdateHandler.indexes(IndexUpdateHandler.java:179) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.table.distributed.index.IndexUpdateHandler.addToIndexes(IndexUpdateHandler.java:68) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.table.distributed.StorageUpdateHandler.tryProcessRow(StorageUpdateHandler.java:173) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.table.distributed.StorageUpdateHandler.lambda$handleUpdate$0(StorageUpdateHandler.java:114) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.storage.pagememory.mv.PersistentPageMemoryMvPartitionStorage.lambda$runConsistently$0(PersistentPageMemoryMvPartitionStorage.java:156) ~[ignite-storage-page-memory-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.storage.pagememory.mv.AbstractPageMemoryMvPartitionStorage.busy(AbstractPageMemoryMvPartitionStorage.java:759) ~[ignite-storage-page-memory-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.storage.pagememory.mv.PersistentPageMemoryMvPartitionStorage.runConsistently(PersistentPageMemoryMvPartitionStorage.java:146) ~[ignite-storage-page-memory-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.storage.ThreadAssertingMvPartitionStorage.runConsistently(ThreadAssertingMvPartitionStorage.java:48) ~[ignite-storage-api-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.table.distributed.raft.snapshot.outgoing.SnapshotAwarePartitionDataStorage.runConsistently(SnapshotAwarePartitionDataStorage.java:76) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.table.distributed.StorageUpdateHandler.handleUpdate(StorageUpdateHandler.java:109) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.table.distributed.raft.PartitionListener.handleUpdateCommand(PartitionListener.java:266) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.internal.table.distributed.raft.PartitionListener.lambda$onWrite$1(PartitionListener.java:202) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
at java.base/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:690) [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:266) [ignite-raft-3.0.0-SNAPSHOT.jar:?]
at org.apache.ignite.raft.jraft.disruptor.StripedDisruptor$StripeEntryHandler.onEvent(StripedDisruptor.java:231) [ignite-raft-3.0.0-SNAPSHOT.jar:?]
at com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:167) [disruptor-4.0.0.jar:?]
at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:122) [disruptor-4.0.0.jar:?]
at java.base/java.lang.Thread.run(Thread.java:834) [?:?] {code}
> 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
> Assignee: 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)