[
https://issues.apache.org/jira/browse/IGNITE-23926?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17904363#comment-17904363
]
Kirill Tkalenko edited comment on IGNITE-23926 at 12/10/24 6:39 AM:
--------------------------------------------------------------------
The error occurs because the test does not have time to finish within the
timeout and starts to fail.
Which results in the execution of sql *DROP TABLE Person*, so transactions that
have not yet finished may have time to see a new version of the catalog in
which the table with its indexes has already been deleted.
Here are the log messages that led to this conclusion:
{noformat}
[05:21:18] : [:ignite-jdbc:integrationTest]
[2024-12-10T05:21:17,676][INFO
][%ijbst_n_0%JRaft-FSMCaller-Disruptor_stripe_4-0][TableUtils] >>>>>
TableUtils#indexIdsAtRwTxBeginTs: [txId=0193af03-bb5f-0020-de3d-986200000001,
txBTs=HybridTimestamp [physical=2024-12-10 05:21:17:663 +0000, logical=32,
composite=113626846177722400], tableId=16, catalogVersion=7, indexSize=1]
[05:21:18] : [:ignite-jdbc:integrationTest]
[2024-12-10T05:21:17,691][INFO ][Test worker][ItJdbcBatchSelfTest] >>> Stopping
test: ItJdbcBatchSelfTest#testHeterogeneousBatchException, displayName:
testHeterogeneousBatchException(), cost: 2043ms.
[05:21:18] : [:ignite-jdbc:integrationTest]
[2024-12-10T05:21:17,691][INFO ][Test worker][JdbcStatement] >>>>>
JdbcStatement#execute: [sql=DROP TABLE Person;, args=[]]
[05:21:18]W: [:ignite-jdbc:integrationTest]
[2024-12-10T05:21:17,799][WARN
][%ijbst_n_0%partition-operations-15][ReplicaManager] Failed to process replica
request [request=WriteIntentSwitchReplicaRequestImpl [commit=false,
commitTimestamp=null, groupId=TablePartitionIdMessageImpl [partitionId=16,
tableId=16], timestamp=HybridTimestamp [physical=2024-12-10 05:21:17:798 +0000,
logical=1, composite=113626846186569729],
txId=0193af03-bbe4-0002-de3d-986200000001]].
[05:21:18]W: [:ignite-jdbc:integrationTest]
java.util.concurrent.CompletionException: java.lang.AssertionError:
txId=0193af03-bbe4-0002-de3d-986200000001, tableId=16, catalogVersion=8
{noformat}
What can be done?
* Improve error message in
*org.apache.ignite.internal.table.distributed.TableUtils#indexIdsAtRwTxBeginTs*.
* Somewhere set the *catalogVersion* at the moment of the transaction start/
and then work with it everywhere, but here we need to check whether there will
be problems if we create new indexes in which we could write data.
Improve error logging:
was (Author: [email protected]):
The error occurs because the test does not have time to finish within the
timeout and starts to fail.
Which results in the execution of sql *DROP TABLE Person*, so transactions that
have not yet finished may have time to see a new version of the catalog in
which the table with its indexes has already been deleted.
Here are the log messages that led to this conclusion:
{noformat}
[05:21:18] : [:ignite-jdbc:integrationTest]
[2024-12-10T05:21:17,676][INFO
][%ijbst_n_0%JRaft-FSMCaller-Disruptor_stripe_4-0][TableUtils] >>>>>
TableUtils#indexIdsAtRwTxBeginTs: [txId=0193af03-bb5f-0020-de3d-986200000001,
txBTs=HybridTimestamp [physical=2024-12-10 05:21:17:663 +0000, logical=32,
composite=113626846177722400], tableId=16, catalogVersion=7, indexSize=1]
[05:21:18] : [:ignite-jdbc:integrationTest]
[2024-12-10T05:21:17,691][INFO ][Test worker][ItJdbcBatchSelfTest] >>> Stopping
test: ItJdbcBatchSelfTest#testHeterogeneousBatchException, displayName:
testHeterogeneousBatchException(), cost: 2043ms.
[05:21:18] : [:ignite-jdbc:integrationTest]
[2024-12-10T05:21:17,691][INFO ][Test worker][JdbcStatement] >>>>>
JdbcStatement#execute: [sql=DROP TABLE Person;, args=[]]
[05:21:18]W: [:ignite-jdbc:integrationTest]
[2024-12-10T05:21:17,799][WARN
][%ijbst_n_0%partition-operations-15][ReplicaManager] Failed to process replica
request [request=WriteIntentSwitchReplicaRequestImpl [commit=false,
commitTimestamp=null, groupId=TablePartitionIdMessageImpl [partitionId=16,
tableId=16], timestamp=HybridTimestamp [physical=2024-12-10 05:21:17:798 +0000,
logical=1, composite=113626846186569729],
txId=0193af03-bbe4-0002-de3d-986200000001]].
[05:21:18]W: [:ignite-jdbc:integrationTest]
java.util.concurrent.CompletionException: java.lang.AssertionError:
txId=0193af03-bbe4-0002-de3d-986200000001, tableId=16, catalogVersion=8
{noformat}
> Investigate the flaky ItJdbcBatchSelfTest
> -----------------------------------------
>
> Key: IGNITE-23926
> URL: https://issues.apache.org/jira/browse/IGNITE-23926
> Project: Ignite
> Issue Type: Task
> Reporter: Kirill Tkalenko
> Assignee: Kirill Tkalenko
> Priority: Major
> Labels: ignite-3
> Time Spent: 10m
> Remaining Estimate: 0h
>
> In
> [JDBC|https://ci.ignite.apache.org/viewLog.html?buildId=8680682&tab=buildResultsDiv&buildTypeId=ApacheIgnite3xGradle_Test_IntegrationTests_ModuleJdbc]
> there is error
> {code:java}
> java.util.concurrent.CompletionException: java.lang.AssertionError:
> txId=01939e8e-3d9a-001c-de3d-986200000001, tableId=16, catalogVersion=8
> {code}
> for *ItJdbcBatchSelfTest*, we need to find out what the reason is.
> StackTrace:
> {noformat}
> [00:39:02]W: [:ignite-jdbc:integrationTest]
> java.util.concurrent.CompletionException: java.lang.AssertionError:
> txId=01939e8e-3d9a-001c-de3d-986200000001, tableId=16, catalogVersion=8
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:315)
> ~[?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.CompletableFuture.uniApplyNow(CompletableFuture.java:687)
> ~[?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:662)
> ~[?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:2168)
> ~[?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.lambda$processWriteIntentSwitchAction$62(PartitionReplicaListener.java:1807)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187)
> ~[?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2309)
> ~[?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.processWriteIntentSwitchAction(PartitionReplicaListener.java:1802)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.processOperationRequest(PartitionReplicaListener.java:763)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.processOperationRequestWithTxRwCounter(PartitionReplicaListener.java:3977)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.processRequest(PartitionReplicaListener.java:536)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.lambda$invoke$1(PartitionReplicaListener.java:473)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187)
> ~[?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2309)
> ~[?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.invoke(PartitionReplicaListener.java:473)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.replicator.ReplicaImpl.processRequest(ReplicaImpl.java:155)
> ~[ignite-replicator-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.replicator.ReplicaManager.handleReplicaRequest(ReplicaManager.java:450)
> ~[ignite-replicator-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.replicator.ReplicaManager.onReplicaMessageReceived(ReplicaManager.java:383)
> ~[ignite-replicator-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.network.DefaultMessagingService.sendToSelf(DefaultMessagingService.java:388)
> ~[ignite-network-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.network.DefaultMessagingService.invoke0(DefaultMessagingService.java:316)
> ~[ignite-network-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.network.DefaultMessagingService.invoke(DefaultMessagingService.java:245)
> ~[ignite-network-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.network.wrapper.JumpToExecutorByConsistentIdAfterSend.invoke(JumpToExecutorByConsistentIdAfterSend.java:97)
> ~[ignite-network-api-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.network.MessagingService.invoke(MessagingService.java:198)
> ~[ignite-network-api-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.replicator.ReplicaService.sendToReplicaRaw(ReplicaService.java:138)
> ~[ignite-replicator-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.replicator.ReplicaService.sendToReplica(ReplicaService.java:122)
> ~[ignite-replicator-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.replicator.ReplicaService.invoke(ReplicaService.java:289)
> ~[ignite-replicator-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.tx.impl.TxMessageSender.switchWriteIntents(TxMessageSender.java:102)
> ~[ignite-transactions-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.tx.impl.WriteIntentSwitchProcessor.switchLocalWriteIntents(WriteIntentSwitchProcessor.java:77)
> ~[ignite-transactions-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.tx.impl.TxCleanupRequestHandler.processTxCleanup(TxCleanupRequestHandler.java:130)
> ~[ignite-transactions-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.tx.impl.TxCleanupRequestHandler.lambda$start$0(TxCleanupRequestHandler.java:108)
> ~[ignite-transactions-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.network.TrackableNetworkMessageHandler.onReceived(TrackableNetworkMessageHandler.java:52)
> ~[ignite-network-api-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.network.DefaultMessagingService.sendToSelf(DefaultMessagingService.java:388)
> ~[ignite-network-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.network.DefaultMessagingService.invoke0(DefaultMessagingService.java:316)
> ~[ignite-network-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.network.DefaultMessagingService.invoke(DefaultMessagingService.java:245)
> ~[ignite-network-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.network.wrapper.JumpToExecutorByConsistentIdAfterSend.invoke(JumpToExecutorByConsistentIdAfterSend.java:97)
> ~[ignite-network-api-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.network.MessagingService.invoke(MessagingService.java:198)
> ~[ignite-network-api-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.tx.impl.TxMessageSender.cleanup(TxMessageSender.java:131)
> ~[ignite-transactions-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.tx.impl.TxCleanupRequestSender.sendCleanupMessageWithRetries(TxCleanupRequestSender.java:240)
> ~[ignite-transactions-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.tx.impl.TxCleanupRequestSender.cleanupPartitions(TxCleanupRequestSender.java:226)
> ~[ignite-transactions-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.tx.impl.TxCleanupRequestSender.cleanup(TxCleanupRequestSender.java:165)
> ~[ignite-transactions-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.tx.impl.TxManagerImpl.cleanup(TxManagerImpl.java:826)
> ~[ignite-transactions-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.lambda$finishAndCleanup$58(PartitionReplicaListener.java:1692)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1150)
> ~[?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
> ~[?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)
> ~[?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.lambda$applyCmdWithRetryOnSafeTimeReorderException$114(PartitionReplicaListener.java:2680)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
> [?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
> [?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
> [?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.CompletableFuture.postFire(CompletableFuture.java:614)
> [?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:653)
> [?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:482)
> [?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
> [?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
> [?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.lang.Thread.run(Thread.java:833) [?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] Caused by:
> java.lang.AssertionError: txId=01939e8e-3d9a-001c-de3d-986200000001,
> tableId=16, catalogVersion=8
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.table.distributed.TableUtils.indexIdsAtRwTxBeginTs(TableUtils.java:58)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.indexIdsAtRwTxBeginTs(PartitionReplicaListener.java:4045)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.applyWriteIntentSwitchCommand(PartitionReplicaListener.java:1882)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.lambda$processWriteIntentSwitchAction$61(PartitionReplicaListener.java:1809)
> ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] at
> java.base/java.util.concurrent.CompletableFuture.uniApplyNow(CompletableFuture.java:684)
> ~[?:?]
> [00:39:02]W: [:ignite-jdbc:integrationTest] ... 53 more
> {noformat}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
