Apicurio Schema Registry error during boot up -Registry working fine though

[ozarkblue]

I've installed Schema Registry 2.4.1.Final version in kubernetes and its working fine.
Seeing below error ( ERROR <> [io.apicurio.registry.downloads.DownloadReaper] (executor-thread-0) Exception thrown when running download reaper job: io.apicurio.registry.storage.RegistryStorageException: java.lang.RuntimeException: )
during initial install though.

Would you pls check and suggest if anything wrong in my setup or how to resolve this?

This is some of config details for my deployment:

Deployment in Kubernetes containers
Apicurio image used:2.4.1.Final from Docker hub (Apicurio/Apicurio-registry-sql)
DB: PostgreSQL – version 11.0 in Azure.

Config Used:
REGISTRY_DATASOURCE_USERNAME: redacted
REGISTRY_DATASOURCE_PASSWORD: redacted
REGISTRY_DATASOURCE_URL: redacted
AUTH_ENABLED: true
ROLE_BASED_AUTHZ_ENABLED: true
REGISTRY_AUTH_OWNER_ONLY_AUTHORIZATION: true
KEYCLOAK_URLredacted
KEYCLOAK_REALM: registry
KEYCLOAK_UI_CLIENT_ID: apicurio-registry
KEYCLOAK_API_CLIENT_ID: registry-api
REGISTRY_UI_CONFIG_APIURL: https://apicurio.dev.**redacted**/apis/registry
REGISTRY_UI_CONFIG_UIURL: https://apicurio.dev redacted/ui
JAVA_TOOL_OPTIONS: -Djavax.net.ssl.trustStore=/etc/secrets/truststore.jks

Log:

E0209 09:56:06.312995 24646 memcache.go:255] couldn't get resource list for custom.metrics.k8s.io/v1beta1: Got empty response for: custom.metrics.k8s.io/v1beta1
Starting the Java application using /opt/jboss/container/java/run/run-java.sh ...
INFO exec java -Dquarkus.http.host=0.0.0.0 -Djava.util.logging.manager=org.jboss.logmanager.LogManager -javaagent:/usr/share/java/jolokia-jvm-agent/jolokia-jvm.jar=config=/opt/jboss/container/jolokia/etc/jolokia.properties -Xms256m -Xmx1024m -XX:+UseParallelGC -XX:MinHeapFreeRatio=10 -XX:MaxHeapFreeRatio=20 -XX:GCTimeRatio=4 -XX:AdaptiveSizePolicyWeight=90 -XX:+ExitOnOutOfMemoryError -cp "." -jar /deployments/apicurio-registry-storage-sql-2.4.1.Final-runner.jar
Picked up JAVA_TOOL_OPTIONS: -Djavax.net.ssl.trustStore=/etc/secrets/truststore.jks
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.jolokia.util.ClassUtil (file:/usr/share/java/jolokia-jvm-agent/jolokia-jvm.jar) to constructor sun.security.x509.X500Name(java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String,java.lang.String)
WARNING: Please consider reporting this to the maintainers of org.jolokia.util.ClassUtil
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
I> No access restrictor found, access to any MBean is allowed
Jolokia: Agent started with URL https://240.**.**.31:8778/jolokia/

---

--/ __ / / / / _ | / _ / /// / / / __/
-/ // / // / __ |/ , / ,< / // /\ \
--___// |//|//||_//
2023-02-09 15:50:36 INFO <> [io.quarkus.bootstrap.runner.Timing] (main) apicurio-registry-storage-sql 2.4.1.Final on JVM (powered by Quarkus 2.14.0.Final) started in 9.512s. Listening on: http://0.0.0.0:8080
2023-02-09 15:50:36 INFO <> [io.quarkus.bootstrap.runner.Timing] (main) Profile prod activated.
2023-02-09 15:50:36 INFO <> [io.quarkus.bootstrap.runner.Timing] (main) Installed features: [agroal, cdi, jdbc-postgresql, micrometer, narayana-jta, oidc, rest-client, rest-client-jackson, resteasy, resteasy-jackson, scheduler, security, servlet, smallrye-context-propagation, smallrye-fault-tolerance, smallrye-health, vertx]
2023-02-09 15:50:37 INFO <> [io.apicurio.registry.storage.RegistryStorageProducer] (executor-thread-0) Using RegistryStore: io.apicurio.registry.storage.impl.sql.SqlRegistryStorage_ClientProxy
2023-02-09 15:50:37 INFO <> [io.apicurio.registry.storage.impl.sql.AbstractSqlRegistryStorage] (executor-thread-0) SqlRegistryStorage constructed successfully. JDBC URL: jdbc:postgresql://pgsql-apicurio-postgres-redacted.database.azure.com:5432/apicurio
2023-02-09 15:50:42 ERROR <> [io.apicurio.registry.downloads.DownloadReaper] (executor-thread-0) Exception thrown when running download reaper job: io.apicurio.registry.storage.RegistryStorageException: java.lang.RuntimeException: java.sql.SQLException: Acquisition timeout while waiting for new connection
at io.apicurio.registry.storage.impl.sql.HandleFactory.withHandleNoException(HandleFactory.java:56)
at io.apicurio.registry.storage.impl.sql.HandleFactory_ClientProxy.withHandleNoException(Unknown Source)
at io.apicurio.registry.storage.impl.sql.AbstractSqlRegistryStorage.initialize(AbstractSqlRegistryStorage.java:211)
at io.apicurio.registry.storage.impl.sql.SqlRegistryStorage_Bean.create(Unknown Source)
at io.apicurio.registry.storage.impl.sql.SqlRegistryStorage_Bean.create(Unknown Source)
at io.quarkus.arc.impl.AbstractSharedContext.createInstanceHandle(AbstractSharedContext.java:113)
at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:37)
at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:34)
at io.quarkus.arc.impl.LazyValue.get(LazyValue.java:26)
at io.quarkus.arc.impl.ComputingCache.computeIfAbsent(ComputingCache.java:69)
at io.quarkus.arc.impl.AbstractSharedContext.get(AbstractSharedContext.java:34)
at io.quarkus.arc.impl.ClientProxies.getApplicationScopedDelegate(ClientProxies.java:21)
at io.apicurio.registry.storage.impl.sql.SqlRegistryStorage_ClientProxy.arc$delegate(Unknown Source)
at io.apicurio.registry.storage.impl.sql.SqlRegistryStorage_ClientProxy.deleteAllExpiredDownloads(Unknown Source)
at io.apicurio.registry.storage.decorator.RegistryStorageDecorator.deleteAllExpiredDownloads(RegistryStorageDecorator.java:897)
at io.apicurio.registry.config.RegistryStorageConfigCache_ClientProxy.deleteAllExpiredDownloads(Unknown Source)
at io.apicurio.registry.storage.RegistryStorageProducer_ProducerMethod_realImpl_cf1c876861dd1c25dca504d30a12bfedeafd47bd_ClientProxy.deleteAllExpiredDownloads(Unknown Source)
at io.apicurio.registry.downloads.DownloadReaper.reap(DownloadReaper.java:62)
at io.apicurio.registry.downloads.DownloadReaper.run(DownloadReaper.java:52)
at io.apicurio.registry.downloads.DownloadReaper_ClientProxy.run(Unknown Source)
at io.apicurio.registry.downloads.DownloadReaper_ScheduledInvoker_run_72e66771a77415a7284d3ae42331659c186071de.invokeBean(Unknown Source)
at io.quarkus.scheduler.common.runtime.DefaultInvoker.invoke(DefaultInvoker.java:24)
at io.quarkus.scheduler.common.runtime.StatusEmitterInvoker.invoke(StatusEmitterInvoker.java:35)
at io.quarkus.scheduler.common.runtime.SkipConcurrentExecutionInvoker.invoke(SkipConcurrentExecutionInvoker.java:37)
at io.quarkus.scheduler.runtime.SimpleScheduler$ScheduledTask.doInvoke(SimpleScheduler.java:333)
at io.quarkus.scheduler.runtime.SimpleScheduler$ScheduledTask$1.handle(SimpleScheduler.java:314)
at io.quarkus.scheduler.runtime.SimpleScheduler$ScheduledTask$1.handle(SimpleScheduler.java:310)
at io.vertx.core.impl.ContextBase.lambda$null$0(ContextBase.java:137)
at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:264)
at io.vertx.core.impl.ContextBase.lambda$executeBlocking$1(ContextBase.java:135)
at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:569)
at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.lang.RuntimeException: java.sql.SQLException: Acquisition timeout while waiting for new connection
at io.apicurio.registry.storage.impl.sql.HandleFactory.withHandle(HandleFactory.java:46)
at io.apicurio.registry.storage.impl.sql.HandleFactory.withHandleNoException(HandleFactory.java:52)
... 36 more
Caused by: java.sql.SQLException: Acquisition timeout while waiting for new connection
at io.agroal.pool.ConnectionPool.handlerFromSharedCache(ConnectionPool.java:320)
at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:248)
at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
at io.apicurio.registry.storage.impl.sql.HandleFactory.withHandle(HandleFactory.java:42)
... 37 more
Caused by: java.util.concurrent.TimeoutException
at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:204)
at io.agroal.pool.ConnectionPool.handlerFromSharedCache(ConnectionPool.java:279)
... 40 more

2023-02-09 15:50:51 INFO <> [io.apicurio.registry.storage.impl.sql.AbstractSqlRegistryStorage] (executor-thread-0) SqlRegistryStorage constructed successfully. JDBC URL: jdbc:postgresql://pgsql-apicurio-postgres-redacted.database.azure.com:5432/apicurio
2023-02-09 15:50:51 INFO <> [io.apicurio.registry.storage.impl.sql.AbstractSqlRegistryStorage] (executor-thread-0) Checking to see if the DB is initialized.
2023-02-09 15:50:51 INFO <> [io.apicurio.registry.storage.impl.sql.AbstractSqlRegistryStorage] (executor-thread-0) Database was already initialized, skipping.
2023-02-09 15:50:51 INFO <> [io.apicurio.registry.storage.impl.sql.AbstractSqlRegistryStorage] (executor-thread-0) Checking to see if the DB is up-to-date.
2023-02-09 15:50:51 INFO <> [io.apicurio.registry.storage.impl.sql.AbstractSqlRegistryStorage] (executor-thread-0) Build's DB version is 11
2023-02-09 15:50:51 INFO <> [io.apicurio.registry.storage.impl.sql.SqlRegistryStorage] (executor-thread-0) Using SQL artifactStore.

[ozarkblue]

@EricWittmann @carlesarnal - your attn pls.

[jsenko]

Is this happening every time you (re)start Registry, or only occasionally? I suspect the cause is that one of the components is trying to access the database before the DB is ready.

[ozarkblue]

Yes,It's happening every time I restart the pods or make a new deployment of Registry in kubernetes cluster with mentioned image.
Application is running fine though and I do not notice any issue.
I'm using Azure PostgreSQL as DB

[jsenko]

Can you test if this fixes the issue #3150 ?

[ozarkblue]

@jsenko @carlesarnal would you pls suggest what image tag and repo to use to test this apicurio-registry-sql?
I just tried with below image from docker hub and its giving same error

Image: latest-snapshot

Error: 2023-02-20 19:27:20 ERROR <> [io.apicurio.registry.downloads.DownloadReaper] (executor-thread-0) Exception thrown when running download reaper job: io.apicurio.registry.storage.RegistryStorageException: java.lang.RuntimeException: java.sql.SQLException: Acquisition timeout while waiting for new connection

[carlesarnal]

@ozarkblue I have added a delay for the class. The problem is that this process is being started before the storage is ready.