Timeout trying to lock table when processing records in multiple threads

[vjuranek]

Description

Registry
Version: 2.5.8.Final
Persistence type: "in-memory"
Docker image: apicurio/apicurio-registry-mem:2.5.8.Final

Environment

Running Apicurio via Docker in a Debezium test.

Steps to Reproduce

Process multiple records in parallel in mutiple threads using either Apicurio json or avro converter.

Logs

Exception thrown on the client side:

2024-02-19 23:03:02,561 ERROR [io.deb.emb.asy.AsyncEmbeddedEngine] (pool-9-thread-1) Engine has failed with : java.util.concurrent.ExecutionException: java.util.concurrent.ExecutionException: io.apicurio.registry.rest.client.exception.RestClientException: io.apicurio.registry.storage.impl.sql.jdb.RuntimeSqlException: org.h2.jdbc.JdbcSQLTimeoutException: Timeout trying to lock table {0}; SQL statement:
INSERT INTO sequences (tenantId, name, seq_value) VALUES (?, ?, ?) [50200-220]
        at java.base/java.util.concurrent.FutureTask.report(FutureTask.java:122)
        at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:191)
        at io.debezium.embedded.async.AsyncEmbeddedEngine.runTasksPolling(AsyncEmbeddedEngine.java:454)
        at io.debezium.embedded.async.AsyncEmbeddedEngine.run(AsyncEmbeddedEngine.java:204)
        at io.debezium.server.DebeziumServer.lambda$start$1(DebeziumServer.java:174)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
        at java.base/java.lang.Thread.run(Thread.java:1583)
Caused by: java.util.concurrent.ExecutionException: io.apicurio.registry.rest.client.exception.RestClientException: io.apicurio.registry.storage.impl.sql.jdb.RuntimeSqlException: org.h2.jdbc.JdbcSQLTimeoutException: Timeout trying to lock table {0}; SQL statement:
INSERT INTO sequences (tenantId, name, seq_value) VALUES (?, ?, ?) [50200-220]
        at java.base/java.util.concurrent.FutureTask.report(FutureTask.java:122)
        at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:191)
        at io.debezium.embedded.async.ParallelSmtAndConvertBatchProcessor.processRecords(ParallelSmtAndConvertBatchProcessor.java:49)
        at io.debezium.embedded.async.AsyncEmbeddedEngine$PollRecords.doCall(AsyncEmbeddedEngine.java:1122)
        at io.debezium.embedded.async.AsyncEmbeddedEngine$PollRecords.doCall(AsyncEmbeddedEngine.java:1103)
        at io.debezium.embedded.async.RetryingCallable.call(RetryingCallable.java:47)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
        ... 3 more
Caused by: io.apicurio.registry.rest.client.exception.RestClientException: io.apicurio.registry.storage.impl.sql.jdb.RuntimeSqlException: org.h2.jdbc.JdbcSQLTimeoutException: Timeout trying to lock table {0}; SQL statement:
INSERT INTO sequences (tenantId, name, seq_value) VALUES (?, ?, ?) [50200-220]
        at io.apicurio.registry.rest.client.impl.ErrorHandler.handleErrorResponse(ErrorHandler.java:64)
        at io.apicurio.rest.client.handler.BodyHandler.lambda$toSupplierOfType$1(BodyHandler.java:54)
        at io.apicurio.rest.client.JdkHttpClient.sendRequest(JdkHttpClient.java:204)
        at io.apicurio.registry.rest.client.impl.RegistryClientImpl.createArtifact(RegistryClientImpl.java:311)
        at io.apicurio.registry.rest.client.RegistryClient.createArtifact(RegistryClient.java:147)
        at io.apicurio.registry.resolver.DefaultSchemaResolver.lambda$handleAutoCreateArtifact$3(DefaultSchemaResolver.java:270)
        at io.apicurio.registry.resolver.ERCache.lambda$getValue$0(ERCache.java:156)
        at io.apicurio.registry.resolver.ERCache.retry(ERCache.java:197)
        at io.apicurio.registry.resolver.ERCache.getValue(ERCache.java:155)
        at io.apicurio.registry.resolver.ERCache.getByContent(ERCache.java:130)
        at io.apicurio.registry.resolver.DefaultSchemaResolver.handleAutoCreateArtifact(DefaultSchemaResolver.java:268)
        at io.apicurio.registry.resolver.DefaultSchemaResolver.getSchemaFromRegistry(DefaultSchemaResolver.java:119)
        at io.apicurio.registry.resolver.DefaultSchemaResolver.resolveSchema(DefaultSchemaResolver.java:90)
        at io.apicurio.registry.utils.converter.ExtJsonConverter.fromConnectData(ExtJsonConverter.java:97)
        at io.apicurio.registry.utils.converter.ExtJsonConverter.fromConnectData(ExtJsonConverter.java:87)
        at io.debezium.embedded.ConverterBuilder.lambda$toFormat$2(ConverterBuilder.java:101)
        at io.debezium.embedded.async.ProcessingCallables$TransformAndConvertRecord.call(ProcessingCallables.java:81)
        ... 4 more

Apicurio log with H2 trace logging is attached as it's too big in insert it direcly here.
apicurio_lock_timeout_exception.log

[EricWittmann]

Note that the in-memory version of Registry is not really intended to be used for production use cases, which is why the priority of this issue was never bumped up very high.

However, we do of course want it to be as robust as possible!

Good news: as part of working on an issue reported against the KafkaSQL storage (which uses the H2 in-memory database as well) I believe I have fixed this issue.

It should be fixed in both 2.6.x and on main (3.0.x):

• [2.6.x] Concurrent artifact creation test & fixes #5169
• [3.x] Concurrent artifact creation test & fixes #5180