[
https://issues.apache.org/jira/browse/IGNITE-21142?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Kirill Tkalenko updated IGNITE-21142:
-------------------------------------
Fix Version/s: 3.0.0-beta2
> "SqlException: Table with name 'N' already exists" upon creating a
> non-existing table
> -------------------------------------------------------------------------------------
>
> Key: IGNITE-21142
> URL: https://issues.apache.org/jira/browse/IGNITE-21142
> Project: Ignite
> Issue Type: Bug
> Components: sql
> Reporter: Ivan Artiukhov
> Assignee: Kirill Tkalenko
> Priority: Blocker
> Labels: ignite-3
> Fix For: 3.0.0-beta2
>
> Time Spent: 20m
> Remaining Estimate: 0h
>
> h1. Steps
> - Start a cluster of 1 node with default settings, init the cluster.
> - Create 1000 unique tables in a loop using
> {{{}IgniteCluster.dataSource().getConnection().createStatement(){}}}:
> Example of a DDL request:
>
> {noformat}
> create table test_table_123(id INTEGER not null, column_1 VARCHAR(50) not
> null, column_2 VARCHAR(50) not null, column_3 VARCHAR(50) not null, column_4
> VARCHAR(50) not null, primary key (id)){noformat}
> h1. Expected result
> All 1000 tables were created successfullt
> h1. Actual result
> The following exception occurs on the server node:
> {noformat}
> 2023-12-21 02:52:27:298 +0000
> [INFO][%TablesAmountCapacityTest_cluster_0%JRaft-FSMCaller-Disruptor-metastorage-_stripe_0-0][JdbcQueryEventHandlerImpl]
> Exception while executing query [query=create table test_table_523(id
> INTEGER not null, column_1 VARCHAR(50) not null, column_2 VARCHAR(50) not
> null, column_3 VARCHAR(50) not null, column_4 VARCHAR(50) not null, primary
> key (id))]
> org.apache.ignite.sql.SqlException: IGN-SQL-6
> TraceId:12fb2fcf-71f1-4373-b85c-71f10b9b58aa Failed to validate query. Table
> with name 'PUBLIC.TEST_TABLE_523' already exists
> at
> org.apache.ignite.internal.sql.engine.util.SqlExceptionMapperProvider.lambda$mappers$3(SqlExceptionMapperProvider.java:60)
> at
> org.apache.ignite.internal.lang.IgniteExceptionMapper.map(IgniteExceptionMapper.java:61)
> at
> org.apache.ignite.internal.lang.IgniteExceptionMapperUtil.map(IgniteExceptionMapperUtil.java:149)
> at
> org.apache.ignite.internal.lang.IgniteExceptionMapperUtil.mapToPublicException(IgniteExceptionMapperUtil.java:103)
> at
> org.apache.ignite.internal.lang.SqlExceptionMapperUtil.mapToPublicSqlException(SqlExceptionMapperUtil.java:49)
> at
> org.apache.ignite.internal.sql.engine.AsyncSqlCursorImpl.wrapIfNecessary(AsyncSqlCursorImpl.java:191)
> at
> org.apache.ignite.internal.sql.engine.AsyncSqlCursorImpl.lambda$requestNextAsync$2(AsyncSqlCursorImpl.java:123)
> at
> java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:934)
> at
> java.base/java.util.concurrent.CompletableFuture.uniHandleStage(CompletableFuture.java:950)
> at
> java.base/java.util.concurrent.CompletableFuture.handle(CompletableFuture.java:2340)
> at
> org.apache.ignite.internal.sql.engine.AsyncSqlCursorImpl.lambda$requestNextAsync$3(AsyncSqlCursorImpl.java:122)
> at
> java.base/java.util.concurrent.CompletableFuture.uniExceptionally(CompletableFuture.java:990)
> at
> java.base/java.util.concurrent.CompletableFuture$UniExceptionally.tryFire(CompletableFuture.java:974)
> at
> java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
> at
> java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162)
> at
> org.apache.ignite.internal.util.AsyncWrapper.lambda$requestNextAsync$2(AsyncWrapper.java:113)
> at
> java.base/java.util.concurrent.CompletableFuture.uniExceptionally(CompletableFuture.java:990)
> at
> java.base/java.util.concurrent.CompletableFuture$UniExceptionally.tryFire(CompletableFuture.java:974)
> at
> java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
> at
> java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)
> at
> org.apache.ignite.internal.util.PendingComparableValuesTracker.lambda$completeWaitersOnUpdate$0(PendingComparableValuesTracker.java:169)
> at
> java.base/java.util.concurrent.ConcurrentMap.forEach(ConcurrentMap.java:122)
> at
> org.apache.ignite.internal.util.PendingComparableValuesTracker.completeWaitersOnUpdate(PendingComparableValuesTracker.java:169)
> at
> org.apache.ignite.internal.util.PendingComparableValuesTracker.update(PendingComparableValuesTracker.java:103)
> at
> org.apache.ignite.internal.catalog.CatalogManagerImpl$OnUpdateHandlerImpl.lambda$handle$1(CatalogManagerImpl.java:439)
> at
> java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
> at
> java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
> at
> java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
> at
> java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)
> at
> org.apache.ignite.internal.raft.RaftGroupServiceImpl.lambda$sendWithRetry$40(RaftGroupServiceImpl.java:573)
> at
> java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
> at
> java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
> at
> java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
> at
> java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)
> at
> org.apache.ignite.network.DefaultMessagingService.onInvokeResponse(DefaultMessagingService.java:398)
> at
> org.apache.ignite.network.DefaultMessagingService.send0(DefaultMessagingService.java:213)
> at
> org.apache.ignite.network.DefaultMessagingService.respond(DefaultMessagingService.java:156)
> at
> org.apache.ignite.network.MessagingService.respond(MessagingService.java:111)
> at
> org.apache.ignite.raft.jraft.rpc.impl.IgniteRpcServer$NetworkRpcContext.sendResponse(IgniteRpcServer.java:246)
> at
> org.apache.ignite.raft.jraft.rpc.impl.ActionRequestProcessor$1.result(ActionRequestProcessor.java:192)
> at
> org.apache.ignite.internal.raft.server.impl.JraftServerImpl$DelegatingStateMachine$1$1.result(JraftServerImpl.java:698)
> at
> org.apache.ignite.internal.metastorage.server.raft.MetaStorageWriteHandler.handleWriteWithTime(MetaStorageWriteHandler.java:176)
> at
> org.apache.ignite.internal.metastorage.server.raft.MetaStorageWriteHandler.handleWriteCommand(MetaStorageWriteHandler.java:97)
> at java.base/java.util.Iterator.forEachRemaining(Iterator.java:133)
> at
> org.apache.ignite.internal.metastorage.server.raft.MetaStorageListener.onWrite(MetaStorageListener.java:153)
> at
> org.apache.ignite.internal.raft.server.impl.JraftServerImpl$DelegatingStateMachine.onApply(JraftServerImpl.java:659)
> at
> org.apache.ignite.raft.jraft.core.FSMCallerImpl.doApplyTasks(FSMCallerImpl.java:557)
> at
> org.apache.ignite.raft.jraft.core.FSMCallerImpl.doCommitted(FSMCallerImpl.java:525)
> at
> org.apache.ignite.raft.jraft.core.FSMCallerImpl.runApplyTask(FSMCallerImpl.java:444)
> at
> org.apache.ignite.raft.jraft.core.FSMCallerImpl$ApplyTaskHandler.onEvent(FSMCallerImpl.java:136)
> at
> org.apache.ignite.raft.jraft.core.FSMCallerImpl$ApplyTaskHandler.onEvent(FSMCallerImpl.java:130)
> at
> org.apache.ignite.raft.jraft.disruptor.StripedDisruptor$StripeEntryHandler.onEvent(StripedDisruptor.java:226)
> at
> org.apache.ignite.raft.jraft.disruptor.StripedDisruptor$StripeEntryHandler.onEvent(StripedDisruptor.java:191)
> at
> com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:137)
> at java.base/java.lang.Thread.run(Thread.java:833)
> Caused by: org.apache.ignite.internal.catalog.TableExistsValidationException:
> IGN-CATALOG-1 TraceId:12fb2fcf-71f1-4373-b85c-71f10b9b58aa Table with name
> 'PUBLIC.TEST_TABLE_523' already exists
> at
> org.apache.ignite.internal.catalog.CatalogParamsValidationUtils.ensureNoTableIndexOrSysViewExistsWithGivenName(CatalogParamsValidationUtils.java:116)
> at
> org.apache.ignite.internal.catalog.commands.CreateTableCommand.get(CreateTableCommand.java:125)
> at
> org.apache.ignite.internal.catalog.CatalogManagerImpl.saveUpdate(CatalogManagerImpl.java:363)
> at
> org.apache.ignite.internal.catalog.CatalogManagerImpl.lambda$saveUpdate$5(CatalogManagerImpl.java:386)
> at
> java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1150)
> ... 37 more{noformat}
> The following TimeoutException is seen before that SQLException:
> {noformat}
> 2023-12-21 02:52:22:941 +0000
> [WARNING][%TablesAmountCapacityTest_cluster_0%vault-1][WatchProcessor] Watch
> event processing has been too long [duration=154,
> keys=[placementdriver.leases]]
> 2023-12-21 02:52:23:410 +0000
> [WARNING][%TablesAmountCapacityTest_cluster_0%vault-2][WatchProcessor] Watch
> event processing has been too long [duration=103,
> keys=[placementdriver.leases]]
> 2023-12-21 02:52:24:001 +0000
> [INFO][TablesAmountCapacityTest_cluster_0-srv-worker-1][ClientInboundMessageHandler]
> Partition primary replica changed, notifying client [connectionId=1,
> remoteAddress=/127.0.0.1:33036]
> 2023-12-21 02:52:27:012 +0000
> [WARNING][CompletableFutureDelayScheduler][RaftGroupServiceImpl] Recoverable
> error during the request occurred (will be retried on the randomly selected
> node) [request=WriteActionRequestImpl [command=[112, 12, -33, 1, 9, -33, 1,
> 11, -33, 1, 8, 3, -33, 1, 6, 19, 99, 97, 116, 97, 108, 111, 103, 46, 117,
> 112, 100, 97, 116, 101, 46, 53, 50, 53, 2, -51, 21, -84, -19, 0, 5, 115, 114,
> 0, 58, 111, 114, 103, 46, 97, 112, 97, 99, 104, 101, 46, 105, 103, 110, 105,
> 116, 101, 46, 105, 110, 116, 101, 114, 110, 97, 108, 46, 99, 97, 116, 97,
> 108, 111, 103, 46, 115, 116, 111, 114, 97, 103, 101, 46, 86, 101, 114, 115,
> 105, 111, 110, 101, 100, 85, 112, 100, 97... and 2802 more],
> deserializedCommand=MultiInvokeCommandImpl [iif=IifImpl
> [andThen=UpdateStatementImpl [update=UpdateImpl [operations=List12
> [OperationImpl [key=[99, 97, 116, 97, 108, 111, 103, 46, 117, 112, 100, 97,
> 116, 101, 46, 53, 50, 53], operationType=1, value=[-84, -19, 0, 5, 115, 114,
> 0, 58, 111, 114, 103, 46, 97, 112, 97, 99, 104, 101, 46, 105, 103, 110, 105,
> 116, 101, 46, 105, 110, 116, 101, 114, 110, 97, 108, 46, 99, 97, 116, 97,
> 108, 111, 103, 46, 115, 116, 111, 114, 97, 103, 101, 46, 86, 101, 114, 115,
> 105, 111, 110, 101, 100, 85, 112, 100, 97, 116, 101, 52, -71, 25, 6, 7, 14,
> 62, 87, 2, 0, 3, 74, 0, 15, 100, 101, 108, 97, 121, 68, 117, 114, 97, 116,
> 105, 111, 110, 77, 115, 73, 0, 7, 118, 101, 114... and 2664 more]],
> OperationImpl [key=[99, 97, 116, 97, 108, 111, 103, 46, 118, 101, 114, 115,
> 105, 111, 110], operationType=1, value=[0, 0, 2, 13]]],
> result=StatementResultImpl [result=[1]]]], condition=CompoundConditionImpl
> [compoundConditionType=1, leftCondition=SimpleConditionImpl
> [conditionType=13, key=[99, 97, 116, 97, 108, 111, 103, 46, 118, 101, 114,
> 115, 105, 111, 110]], rightCondition=ValueConditionImpl [conditionType=6,
> key=[99, 97, 116, 97, 108, 111, 103, 46, 118, 101, 114, 115, 105, 111, 110],
> value=[0, 0, 2, 12]]], orElse=UpdateStatementImpl [update=UpdateImpl
> [operations=ListN [], result=StatementResultImpl [result=[0]]]]],
> initiatorTimeLong=111616140509446144, safeTimeLong=111616140509446146],
> groupId=metastorage_group], peer=Peer
> [consistentId=TablesAmountCapacityTest_cluster_0, idx=0]].
> java.util.concurrent.CompletionException:
> java.util.concurrent.TimeoutException
> at
> java.base/java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:368)
> at
> java.base/java.util.concurrent.CompletableFuture.completeRelay(CompletableFuture.java:377)
> at
> java.base/java.util.concurrent.CompletableFuture$UniRelay.tryFire(CompletableFuture.java:1097)
> at
> java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
> at
> java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162)
> at
> java.base/java.util.concurrent.CompletableFuture$Timeout.run(CompletableFuture.java:2874)
> at
> java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
> at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
> at
> java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
> at
> java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
> at
> java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
> at java.base/java.lang.Thread.run(Thread.java:833)
> Caused by: java.util.concurrent.TimeoutException
> ... 7 more
> 2023-12-21 02:52:27:094 +0000
> [INFO][%TablesAmountCapacityTest_cluster_0%metastorage-watch-executor-0][IndexManager]
> Creating local index: name=TEST_TABLE_523_PK, id=1052, tableId=1051,
> token=3622{noformat}
> So it looks like some part of the {{create table test_table_523 ...}} request
> was somehow retried by the node itself and hence the {{Table with name
> 'PUBLIC.TEST_TABLE_523' already exists}} error.
> The issue was reproduced only once in a few tries.
>
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
