Hibernate schema validation is flaky and fails due missing tables (while the tables are present)

[AnastasiiaL]

Describe the bug

When running integration tests on the project - it fails around 10% of the time locally, and more often on CI. The error shown is java.lang.RuntimeException: Failed to start quarkus ... Caused by: org.hibernate.tool.schema.spi.SchemaManagementException: Schema-validation: missing table [Limits].

I saw there was already an issue created about the same flakiness earlier (#34187) and it was closed due to the missing reproducible, so I stripped down the project to the minimal setup when the issue still happens and made it available here - https://github.com/AnastasiiaL/flaky-cms.

Expected behavior

No flakiness while executing integration tests

Actual behavior

flaky around 10% of the time on my local machine, more often on CI. Perhaps can be triggered more often with restrained resources.

The stack trace:

[ERROR] Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 18.17 s <<< FAILURE! -- in nl.cms.error.CMSExceptionMapperTest
[ERROR] nl.cms.error.CMSExceptionMapperTest.shouldReturnGeneralExceptionAPICall -- Time elapsed: 0.004 s <<< ERROR!
java.lang.RuntimeException: java.lang.RuntimeException: Failed to start quarkus
        at io.quarkus.test.junit.QuarkusTestExtension.throwBootFailureException(QuarkusTestExtension.java:638)
        at io.quarkus.test.junit.QuarkusTestExtension.interceptTestClassConstructor(QuarkusTestExtension.java:722)
        at java.base/java.util.Optional.orElseGet(Optional.java:364)
        at java.base/java.util.ArrayList.forEach(ArrayList.java:1596)
        at java.base/java.util.ArrayList.forEach(ArrayList.java:1596)
Caused by: java.lang.RuntimeException: Failed to start quarkus
        at io.quarkus.runner.ApplicationImpl.doStart(Unknown Source)
        at io.quarkus.runtime.Application.start(Application.java:101)
        at java.base/java.lang.reflect.Method.invoke(Method.java:580)
        at io.quarkus.runner.bootstrap.StartupActionImpl.run(StartupActionImpl.java:285)
        at io.quarkus.test.junit.QuarkusTestExtension.doJavaStart(QuarkusTestExtension.java:252)
        at io.quarkus.test.junit.QuarkusTestExtension.ensureStarted(QuarkusTestExtension.java:605)
        at io.quarkus.test.junit.QuarkusTestExtension.beforeAll(QuarkusTestExtension.java:655)
        ... 1 more
Caused by: jakarta.persistence.PersistenceException: [PersistenceUnit: <default>] Unable to build Hibernate SessionFactory
        at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.persistenceException(FastBootEntityManagerFactoryBuilder.java:129)
        at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:89)
        at io.quarkus.hibernate.orm.runtime.FastBootHibernatePersistenceProvider.createEntityManagerFactory(FastBootHibernatePersistenceProvider.java:72)
        at jakarta.persistence.Persistence.createEntityManagerFactory(Persistence.java:80)
        at jakarta.persistence.Persistence.createEntityManagerFactory(Persistence.java:55)
        at io.quarkus.hibernate.orm.runtime.JPAConfig$LazyPersistenceUnit.get(JPAConfig.java:157)
        at io.quarkus.hibernate.orm.runtime.JPAConfig.getEntityManagerFactory(JPAConfig.java:105)
        at io.quarkus.hibernate.orm.runtime.metrics.HibernateMetricsRecorder$1.accept(HibernateMetricsRecorder.java:31)
        at io.quarkus.hibernate.orm.runtime.metrics.HibernateMetricsRecorder$1.accept(HibernateMetricsRecorder.java:26)
        at io.quarkus.micrometer.runtime.MicrometerRecorder.registerMetrics(MicrometerRecorder.java:229)
        at io.quarkus.deployment.steps.MicrometerProcessor$configureRegistry477897979.deploy_0(Unknown Source)
        at io.quarkus.deployment.steps.MicrometerProcessor$configureRegistry477897979.deploy(Unknown Source)
        ... 8 more
Caused by: org.hibernate.tool.schema.spi.SchemaManagementException: Schema-validation: missing table [Limits]
        at org.hibernate.tool.schema.internal.AbstractSchemaValidator.validateTable(AbstractSchemaValidator.java:134)
        at org.hibernate.tool.schema.internal.GroupedSchemaValidatorImpl.validateTables(GroupedSchemaValidatorImpl.java:46)
        at org.hibernate.tool.schema.internal.AbstractSchemaValidator.performValidation(AbstractSchemaValidator.java:97)
        at org.hibernate.tool.schema.internal.AbstractSchemaValidator.doValidation(AbstractSchemaValidator.java:75)
        at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.performDatabaseAction(SchemaManagementToolCoordinator.java:295)
        at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.lambda$process$5(SchemaManagementToolCoordinator.java:145)
        at java.base/java.util.HashMap.forEach(HashMap.java:1429)
        at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.process(SchemaManagementToolCoordinator.java:142)
        at io.quarkus.hibernate.orm.runtime.observers.SessionFactoryObserverForSchemaExport.sessionFactoryCreated(SessionFactoryObserverForSchemaExport.java:21)
        at org.hibernate.internal.SessionFactoryObserverChain.sessionFactoryCreated(SessionFactoryObserverChain.java:35)
        at org.hibernate.internal.SessionFactoryImpl.<init>(SessionFactoryImpl.java:315)
        at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:87)
        ... 18 more

[INFO] Running nl.cms.resource.LimitsResourceTest
[INFO] Tests run: 0, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0 s -- in nl.cms.resource.LimitsResourceTest
[INFO] Running nl.cms.resource.TestResourceTest
[INFO] Tests run: 0, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.001 s -- in nl.cms.resource.TestResourceTest
[INFO] 
[INFO] Results:
[INFO] 
[ERROR] Errors: 
[ERROR]   CMSExceptionMapperTest.shouldReturnGeneralExceptionAPICall » Runtime java.lang.RuntimeException: Failed to start quarkus

How to Reproduce?

https://github.com/AnastasiiaL/flaky-cms.

Running the application:

• For the first time run: ./mvnw install -DskipTests
• then ./mvnw verify

Output of uname -a or ver

Darwin Kernel Version 23.3.0

Output of java -version

21.0.2

Quarkus version or git rev

3.8.1

Build tool (ie. output of mvnw --version or gradlew --version)

Apache Maven 3.9.5

Additional information

No response

[quarkus-bot]

/cc @gsmet (hibernate-orm), @yrodiere (hibernate-orm)

[wjglerum]

I've noticed this behaviour too, most notably going from Quarkus 2.x to Quarkus 3.x

[geoand]

I'll try and have a look soon

[marko-bekhta]

hey @geoand, I've tried reproducing this last week with no luck ... also note that the example seems to use MSSQL and if you are on the latest Fedora, you may have a problem starting the DB (microsoft/mssql-docker#868) depending on your kernel version ...

[geoand]

Thanks for the heads up!

I'll give it a shot and see if there is anything different for my case

[gsmet]

If it's a timing issue and happening on CI, you might need to slow down things.

…

On Mon, Mar 11, 2024 at 7:15 PM Georgios Andrianakis < ***@***.***> wrote: Thanks for the heads up! I'll give it a shot and see if there is anything different for my case — Reply to this email directly, view it on GitHub <#39145 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAJYOBP7RM4BAGG4U2DBYMTYXXYFJAVCNFSM6AAAAABEEZFQIGVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSOBZGEZTEMRSHE> . You are receiving this because you were mentioned.Message ID: ***@***.***>

[wjglerum]

If it's a timing issue and happening on CI, you might need to slow down things.
…
On Mon, Mar 11, 2024 at 7:15 PM Georgios Andrianakis < @.> wrote: Thanks for the heads up! I'll give it a shot and see if there is anything different for my case — Reply to this email directly, view it on GitHub <#39145 (comment)>, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAJYOBP7RM4BAGG4U2DBYMTYXXYFJAVCNFSM6AAAAABEEZFQIGVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSOBZGEZTEMRSHE . You are receiving this because you were mentioned.Message ID: @.>

We've also seen this sporadically on deployments to our various environments, were we temporarily had to disable Hibernate schema validation. But is was most notably happening on CI.

I do suspect that it's a timing issue somehow, that the Hibernate validation kicks in just before Flyway was able to run the migrations.

[Sanne]

N.B. the Hibernate ORM extension is booting Hibernate in a secondary thread; this was done out of concerns that booting it was potentially going to take a long time. I don't remember the details, just a suggestion as to what to look into :)

AFAIR there's some form of latch ensuring this is fully completed before Quarkus is considered booted, but I guess this latch might not be fully in synch with expectations of other extensions which manage the schema.

[geoand]

Thanks for the input folks.

As I was not able to reproduce the problem (which is what I expected TBH), @AnastasiiaL could you update the description with the entire stacktrace of the exception you are getting?

[wjglerum]

As I was not able to reproduce the problem (which is what I expected TBH), @AnastasiiaL could you update the description with the entire stacktrace of the exception you are getting?

This is what happens regurarly on our CI jobs, stacktrace from this morning:

java.lang.RuntimeException: java.lang.RuntimeException: Failed to start quarkus
	at io.quarkus.test.junit.QuarkusTestExtension.throwBootFailureException(QuarkusTestExtension.java:638)
	at io.quarkus.test.junit.QuarkusTestExtension.interceptTestClassConstructor(QuarkusTestExtension.java:722)
	at java.base/java.util.Optional.orElseGet(Optional.java:364)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
Caused by: java.lang.RuntimeException: Failed to start quarkus
	at io.quarkus.runner.ApplicationImpl.doStart(Unknown Source)
	at io.quarkus.runtime.Application.start(Application.java:101)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at io.quarkus.runner.bootstrap.StartupActionImpl.run(StartupActionImpl.java:285)
	at io.quarkus.test.junit.QuarkusTestExtension.doJavaStart(QuarkusTestExtension.java:252)
	at io.quarkus.test.junit.QuarkusTestExtension.ensureStarted(QuarkusTestExtension.java:605)
	at io.quarkus.test.junit.QuarkusTestExtension.beforeAll(QuarkusTestExtension.java:655)
	... 1 more
Caused by: jakarta.persistence.PersistenceException: [PersistenceUnit: <default>] Unable to build Hibernate SessionFactory
	at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.persistenceException(FastBootEntityManagerFactoryBuilder.java:129)
	at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:89)
	at io.quarkus.hibernate.orm.runtime.FastBootHibernatePersistenceProvider.createEntityManagerFactory(FastBootHibernatePersistenceProvider.java:72)
	at jakarta.persistence.Persistence.createEntityManagerFactory(Persistence.java:80)
	at jakarta.persistence.Persistence.createEntityManagerFactory(Persistence.java:55)
	at io.quarkus.hibernate.orm.runtime.JPAConfig$LazyPersistenceUnit.get(JPAConfig.java:157)
	at io.quarkus.hibernate.orm.runtime.JPAConfig.getEntityManagerFactory(JPAConfig.java:105)
	at io.quarkus.hibernate.orm.runtime.metrics.HibernateMetricsRecorder$1.accept(HibernateMetricsRecorder.java:31)
	at io.quarkus.hibernate.orm.runtime.metrics.HibernateMetricsRecorder$1.accept(HibernateMetricsRecorder.java:26)
	at io.quarkus.micrometer.runtime.MicrometerRecorder.registerMetrics(MicrometerRecorder.java:229)
	at io.quarkus.deployment.steps.MicrometerProcessor$configureRegistry477897979.deploy_0(Unknown Source)
	at io.quarkus.deployment.steps.MicrometerProcessor$configureRegistry477897979.deploy(Unknown Source)
	... 8 more
Caused by: org.hibernate.tool.schema.spi.SchemaManagementException: Schema-validation: missing table [<<table_name>>]
	at org.hibernate.tool.schema.internal.AbstractSchemaValidator.validateTable(AbstractSchemaValidator.java:134)
	at org.hibernate.tool.schema.internal.GroupedSchemaValidatorImpl.validateTables(GroupedSchemaValidatorImpl.java:46)
	at org.hibernate.tool.schema.internal.AbstractSchemaValidator.performValidation(AbstractSchemaValidator.java:97)
	at org.hibernate.tool.schema.internal.AbstractSchemaValidator.doValidation(AbstractSchemaValidator.java:75)
	at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.performDatabaseAction(SchemaManagementToolCoordinator.java:295)
	at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.lambda$process$5(SchemaManagementToolCoordinator.java:145)
	at java.base/java.util.HashMap.forEach(HashMap.java:1421)
	at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.process(SchemaManagementToolCoordinator.java:142)
	at io.quarkus.hibernate.orm.runtime.observers.SessionFactoryObserverForSchemaExport.sessionFactoryCreated(SessionFactoryObserverForSchemaExport.java:21)
	at org.hibernate.internal.SessionFactoryObserverChain.sessionFactoryCreated(SessionFactoryObserverChain.java:35)
	at org.hibernate.internal.SessionFactoryImpl.<init>(SessionFactoryImpl.java:315)
	at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:87)
	... 18 more

And the startup logs just before that:

2024-03-12 06:55:22,553 INFO  [org.tes.doc.DockerClientProviderStrategy] (build-30) Loaded org.testcontainers.dockerclient.UnixSocketClientProviderStrategy from ~/.testcontainers.properties, will try it first
2024-03-12 06:55:23,039 INFO  [org.tes.doc.DockerClientProviderStrategy] (build-30) Found Docker environment with local Unix socket (unix:///var/run/docker.sock)
2024-03-12 06:55:23,041 INFO  [org.tes.DockerClientFactory] (build-30) Docker host IP address is localhost
2024-03-12 06:55:23,073 INFO  [org.tes.DockerClientFactory] (build-30) Connected to docker: 
  Server Version: 24.0.9
  API Version: 1.43
  Operating System: Ubuntu 22.04.4 LTS
  Total Memory: 6921 MB
2024-03-12 06:55:23,099 INFO  [org.tes.ima.PullPolicy] (build-30) Image pull policy will be performed by: DefaultPullPolicy()
2024-03-12 06:55:23,101 INFO  [org.tes.uti.ImageNameSubstitutor] (build-30) Image name substitution will be performed by: DefaultImageNameSubstitutor (composite of 'ConfigurationFileImageNameSubstitutor' and 'PrefixingImageNameSubstitutor')
2024-03-12 06:55:23,108 INFO  [org.tes.DockerClientFactory] (build-30) Checking the system...
2024-03-12 06:55:23,109 INFO  [org.tes.DockerClientFactory] (build-30) ✔︎ Docker server version should be at least 1.6.0
2024-03-12 06:55:23,169 INFO  [tc.mcr.mic.com/mssql/server:2022-latest] (build-30) Creating container for image: mcr.microsoft.com/mssql/server:2022-latest
2024-03-12 06:55:23,191 WARN  [tc.mcr.mic.com/mssql/server:2022-latest] (build-30) Reuse was requested but the environment does not support the reuse of containers
To enable reuse of containers, you must set 'testcontainers.reuse.enable=true' in a file located at /home/runner/.testcontainers.properties
2024-03-12 06:55:23,201 INFO  [tc.tes.6.0] (build-30) Creating container for image: testcontainers/ryuk:0.6.0
2024-03-12 06:55:23,629 INFO  [tc.tes.6.0] (build-30) Container testcontainers/ryuk:0.6.0 is starting: 256a32317fd53304d09e1f00af3625da5640332ef4861f1532701471edcc0c46
2024-03-12 06:55:24,182 INFO  [io.qua.oid.dep.dev.key.KeycloakDevServicesProcessor] (build-35) Using Quarkus powered Keycloak distribution
2024-03-12 06:55:24,243 INFO  [tc.tes.6.0] (build-30) Container testcontainers/ryuk:0.6.0 started in PT1.042204604S
2024-03-12 06:55:24,252 INFO  [tc.qua.io/.0.7] (build-35) Pulling docker image: quay.io/keycloak/keycloak:23.0.7. Please be patient; this may take some time but only needs to be done once.
2024-03-12 06:55:24,273 INFO  [tc.mcr.mic.com/mssql/server:2022-latest] (build-30) Container mcr.microsoft.com/mssql/server:2022-latest is starting: e7da8f5ac77903afcc0993ffcb65e178ca01f0ebc661b5b5ad3cc97f4aeae606
2024-03-12 06:55:24,663 INFO  [tc.mcr.mic.com/mssql/server:2022-latest] (build-30) Waiting for database connection to become available at jdbc:sqlserver://localhost:32771 using query 'SELECT 1'
2024-03-12 06:55:25,204 INFO  [tc.qua.io/.0.7] (docker-java-stream--136142204) Starting to pull image
2024-03-12 06:55:25,253 INFO  [tc.qua.io/.0.7] (docker-java-stream--136142204) Pulling image layers:  0 pending,  0 downloaded,  0 extracted, (0 bytes/0 bytes)
2024-03-12 06:55:25,343 WARNING [com.mic.sql.jdb.int.SQLServerConnection] (build-30) ConnectionID:1 ClientConnectionId: 07fa7be9-b076-490a-bd09-cd4c3217e75a Prelogin error: host localhost port 32771 Unexpected end of prelogin response after 0 bytes read
2024-03-12 06:55:25,475 WARNING [com.mic.sql.jdb.int.SQLServerConnection] (build-30) ConnectionID:1 ClientConnectionId: 32369870-5500-42dd-85c5-e009e9b8fef4 Prelogin error: host localhost port 32771 Unexpected end of prelogin response after 0 bytes read
2024-03-12 06:55:25,679 WARNING [com.mic.sql.jdb.int.SQLServerConnection] (build-30) ConnectionID:1 ClientConnectionId: d034ec86-296f-4905-8749-c5c7e0221eac Prelogin error: host localhost port 32771 Unexpected end of prelogin response after 0 bytes read
2024-03-12 06:55:25,856 INFO  [tc.qua.io/.0.7] (docker-java-stream--136142204) Pulling image layers:  3 pending,  1 downloaded,  0 extracted, (7 MB/? MB)
2024-03-12 06:55:26,082 WARNING [com.mic.sql.jdb.int.SQLServerConnection] (build-30) ConnectionID:1 ClientConnectionId: 7e7e5253-7b71-42a9-89e0-e5d6348e1aec Prelogin error: host localhost port 32771 Unexpected end of prelogin response after 0 bytes read
2024-03-12 06:55:26,186 INFO  [tc.qua.io/.0.7] (docker-java-stream--136142204) Pulling image layers:  2 pending,  2 downloaded,  0 extracted, (31 MB/? MB)
2024-03-12 06:55:27,014 WARNING [com.mic.sql.jdb.int.SQLServerConnection] (build-30) ConnectionID:1 ClientConnectionId: f5745e23-db03-49c6-91ad-4a052bfc77a9 Prelogin error: host localhost port 32771 Error reading prelogin response: Connection reset ClientConnectionId:f5745e23-db03-49c6-91ad-4a052bfc77a9
2024-03-12 06:55:27,610 INFO  [tc.qua.io/.0.7] (docker-java-stream--136142204) Pulling image layers:  1 pending,  3 downloaded,  0 extracted, (127 MB/? MB)
2024-03-12 06:55:28,028 WARNING [com.mic.sql.jdb.int.SQLServerConnection] (build-30) ConnectionID:1 ClientConnectionId: 1931c744-b314-4ba4-9338-7aeb8ca3a58d Prelogin error: host localhost port 32771 Error reading prelogin response: Connection reset ClientConnectionId:1931c744-b314-4ba4-9338-7aeb8ca3a58d
2024-03-12 06:55:28,597 INFO  [tc.qua.io/.0.7] (docker-java-stream--136142204) Pulling image layers:  1 pending,  3 downloaded,  1 extracted, (180 MB/? MB)
2024-03-12 06:55:29,032 WARNING [com.mic.sql.jdb.int.SQLServerConnection] (build-30) ConnectionID:1 ClientConnectionId: 90fa90a1-4f69-4b76-bce7-12c2af00346d Prelogin error: host localhost port 32771 Error reading prelogin response: Connection reset ClientConnectionId:90fa90a1-4f69-4b76-bce7-12c2af00346d
2024-03-12 06:55:30,049 WARNING [com.mic.sql.jdb.int.SQLServerConnection] (build-30) ConnectionID:1 ClientConnectionId: ae625073-94d9-42d5-a788-5f257fc6700e Prelogin error: host localhost port 32771 Error reading prelogin response: Connection reset ClientConnectionId:ae625073-94d9-42d5-a788-5f257fc6700e
2024-03-12 06:55:30,439 INFO  [tc.qua.io/.0.7] (docker-java-stream--136142204) Pulling image layers:  0 pending,  4 downloaded,  1 extracted, (245 MB/250 MB)
2024-03-12 06:55:31,060 WARNING [com.mic.sql.jdb.int.SQLServerConnection] (build-30) ConnectionID:1 ClientConnectionId: 685df612-f5aa-47f2-a6db-34734023b509 Prelogin error: host localhost port 32771 Error reading prelogin response: Connection reset ClientConnectionId:685df612-f5aa-47f2-a6db-34734023b509
2024-03-12 06:55:32,073 WARNING [com.mic.sql.jdb.int.SQLServerConnection] (build-30) ConnectionID:1 ClientConnectionId: 55bcdf6c-b676-447f-ba4d-e31461c1bf8d Prelogin error: host localhost port 32771 Error reading prelogin response: Connection reset ClientConnectionId:55bcdf6c-b676-447f-ba4d-e31461c1bf8d
2024-03-12 06:55:35,374 INFO  [tc.mcr.mic.com/mssql/server:2022-latest] (build-30) Container mcr.microsoft.com/mssql/server:2022-latest started in PT12.205060992S
2024-03-12 06:55:35,377 INFO  [tc.mcr.mic.com/mssql/server:2022-latest] (build-30) Container is started (JDBC URL: jdbc:sqlserver://localhost:32771;encrypt=false)
2024-03-12 06:55:35,381 INFO  [io.qua.dev.mss.dep.MSSQLDevServicesProcessor] (build-30) Dev Services for Microsoft SQL Server started.
2024-03-12 06:55:35,383 INFO  [io.qua.dat.dep.dev.DevServicesDatasourceProcessor] (build-30) Dev Services for default datasource (mssql) started - container ID is e7da8f5ac779
2024-03-12 06:55:35,739 INFO  [tc.qua.io/.0.7] (docker-java-stream--136142204) Pulling image layers:  0 pending,  4 downloaded,  2 extracted, (248 MB/250 MB)
2024-03-12 06:55:37,371 INFO  [tc.qua.io/.0.7] (docker-java-stream--136142204) Pulling image layers:  0 pending,  4 downloaded,  3 extracted, (250 MB/250 MB)
2024-03-12 06:55:38,030 INFO  [tc.qua.io/.0.7] (docker-java-stream--136142204) Pulling image layers:  0 pending,  4 downloaded,  4 extracted, (250 MB/250 MB)
2024-03-12 06:55:38,039 INFO  [tc.qua.io/.0.7] (docker-java-stream--136142204) Pull complete. 4 layers, pulled in 12s (downloaded 250 MB at 20 MB/s)
2024-03-12 06:55:38,039 INFO  [tc.qua.io/.0.7] (build-35) Image quay.io/keycloak/keycloak:23.0.7 pull took PT13.786234471S
2024-03-12 06:55:38,049 INFO  [tc.qua.io/.0.7] (build-35) Creating container for image: quay.io/keycloak/keycloak:23.0.7
2024-03-12 06:55:38,070 INFO  [tc.qua.io/.0.7] (build-35) Container quay.io/keycloak/keycloak:23.0.7 is starting: 49dc9f5993ad2f6d3075ab7b0ae42ed16994acf7cce23537c752f6bb9fc16193
2024-03-12 06:56:10,030 INFO  [tc.qua.io/.0.7] (build-35) Container quay.io/keycloak/keycloak:23.0.7 started in PT31.981656693S
2024-03-12 06:56:13,714 INFO  [io.qua.oid.dep.dev.key.KeycloakDevServicesProcessor] (build-35) Dev Services for Keycloak started.

[geoand]

Thanks for the info.

As I am not really familiar with the Hibernate ORM extension (and given I can't reproduce the problem locally), I don't think I can provide much help here...
One thing I would ask however is to test and see if the problem still occurs when quarkus.hibernate-orm.metrics.enabled is set to false.

[wjglerum]

Thanks for the info.

As I am not really familiar with the Hibernate ORM extension (and given I can't reproduce the problem locally), I don't think I can provide much help here...

Probably if you restrain the resources (cpu/ram) for your Docker env it should be easier to reproduce this issue.

One thing I would ask however is to test and see if the problem still occurs when quarkus.hibernate-orm.metrics.enabled is set to false.

We will give that a try 👍

[AnastasiiaL]

Thanks for looking into it.

To trigger the problem locally I have to run it around 5-10times.

The stack trace from the shared sample app:

[ERROR] Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 18.17 s <<< FAILURE! -- in nl.cms.error.CMSExceptionMapperTest
[ERROR] nl.cms.error.CMSExceptionMapperTest.shouldReturnGeneralExceptionAPICall -- Time elapsed: 0.004 s <<< ERROR!
java.lang.RuntimeException: java.lang.RuntimeException: Failed to start quarkus
        at io.quarkus.test.junit.QuarkusTestExtension.throwBootFailureException(QuarkusTestExtension.java:638)
        at io.quarkus.test.junit.QuarkusTestExtension.interceptTestClassConstructor(QuarkusTestExtension.java:722)
        at java.base/java.util.Optional.orElseGet(Optional.java:364)
        at java.base/java.util.ArrayList.forEach(ArrayList.java:1596)
        at java.base/java.util.ArrayList.forEach(ArrayList.java:1596)
Caused by: java.lang.RuntimeException: Failed to start quarkus
        at io.quarkus.runner.ApplicationImpl.doStart(Unknown Source)
        at io.quarkus.runtime.Application.start(Application.java:101)
        at java.base/java.lang.reflect.Method.invoke(Method.java:580)
        at io.quarkus.runner.bootstrap.StartupActionImpl.run(StartupActionImpl.java:285)
        at io.quarkus.test.junit.QuarkusTestExtension.doJavaStart(QuarkusTestExtension.java:252)
        at io.quarkus.test.junit.QuarkusTestExtension.ensureStarted(QuarkusTestExtension.java:605)
        at io.quarkus.test.junit.QuarkusTestExtension.beforeAll(QuarkusTestExtension.java:655)
        ... 1 more
Caused by: jakarta.persistence.PersistenceException: [PersistenceUnit: <default>] Unable to build Hibernate SessionFactory
        at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.persistenceException(FastBootEntityManagerFactoryBuilder.java:129)
        at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:89)
        at io.quarkus.hibernate.orm.runtime.FastBootHibernatePersistenceProvider.createEntityManagerFactory(FastBootHibernatePersistenceProvider.java:72)
        at jakarta.persistence.Persistence.createEntityManagerFactory(Persistence.java:80)
        at jakarta.persistence.Persistence.createEntityManagerFactory(Persistence.java:55)
        at io.quarkus.hibernate.orm.runtime.JPAConfig$LazyPersistenceUnit.get(JPAConfig.java:157)
        at io.quarkus.hibernate.orm.runtime.JPAConfig.getEntityManagerFactory(JPAConfig.java:105)
        at io.quarkus.hibernate.orm.runtime.metrics.HibernateMetricsRecorder$1.accept(HibernateMetricsRecorder.java:31)
        at io.quarkus.hibernate.orm.runtime.metrics.HibernateMetricsRecorder$1.accept(HibernateMetricsRecorder.java:26)
        at io.quarkus.micrometer.runtime.MicrometerRecorder.registerMetrics(MicrometerRecorder.java:229)
        at io.quarkus.deployment.steps.MicrometerProcessor$configureRegistry477897979.deploy_0(Unknown Source)
        at io.quarkus.deployment.steps.MicrometerProcessor$configureRegistry477897979.deploy(Unknown Source)
        ... 8 more
Caused by: org.hibernate.tool.schema.spi.SchemaManagementException: Schema-validation: missing table [Limits]
        at org.hibernate.tool.schema.internal.AbstractSchemaValidator.validateTable(AbstractSchemaValidator.java:134)
        at org.hibernate.tool.schema.internal.GroupedSchemaValidatorImpl.validateTables(GroupedSchemaValidatorImpl.java:46)
        at org.hibernate.tool.schema.internal.AbstractSchemaValidator.performValidation(AbstractSchemaValidator.java:97)
        at org.hibernate.tool.schema.internal.AbstractSchemaValidator.doValidation(AbstractSchemaValidator.java:75)
        at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.performDatabaseAction(SchemaManagementToolCoordinator.java:295)
        at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.lambda$process$5(SchemaManagementToolCoordinator.java:145)
        at java.base/java.util.HashMap.forEach(HashMap.java:1429)
        at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.process(SchemaManagementToolCoordinator.java:142)
        at io.quarkus.hibernate.orm.runtime.observers.SessionFactoryObserverForSchemaExport.sessionFactoryCreated(SessionFactoryObserverForSchemaExport.java:21)
        at org.hibernate.internal.SessionFactoryObserverChain.sessionFactoryCreated(SessionFactoryObserverChain.java:35)
        at org.hibernate.internal.SessionFactoryImpl.<init>(SessionFactoryImpl.java:315)
        at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:87)
        ... 18 more

[INFO] Running nl.cms.resource.LimitsResourceTest
[INFO] Tests run: 0, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0 s -- in nl.cms.resource.LimitsResourceTest
[INFO] Running nl.cms.resource.TestResourceTest
[INFO] Tests run: 0, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.001 s -- in nl.cms.resource.TestResourceTest
[INFO] 
[INFO] Results:
[INFO] 
[ERROR] Errors: 
[ERROR]   CMSExceptionMapperTest.shouldReturnGeneralExceptionAPICall » Runtime java.lang.RuntimeException: Failed to start quarkus

[geoand]

Thanks!

Can you also try with the setting I mentioned above?
I have a suspition that the inclusion of metrics is causing this problem

[AnastasiiaL]

disabling quarkus.hibernate-orm.metrics.enabled seems to prevent the issue from recurring locally. I will try to push it to CI now and will let you know how that goes

[AnastasiiaL]

I ran the job on CI 6 times without failing, whereas before it would fail every second time there. So there's definitely an improvement

[geoand]

Can someone give #39352 a try?

[AnastasiiaL]

I tried building that version locally and testing the sample app against it, but I had a chain of problems and the last one I have no clue how to resolve, sorry:

[ERROR] Failed to execute goal io.quarkus:quarkus-maven-plugin:999-SNAPSHOT:build (default) on project cms-webapp: Failed to build quarkus application: io.quarkus.builder.BuildException: Build failure: Build failed due to errors
[ERROR]         [error]: Build step io.quarkus.resteasy.reactive.server.deployment.ResteasyReactiveProcessor#buildSetup threw an exception: java.lang.NoSuchFieldError: Class io.quarkus.deployment.Feature does not have member field 'io.quarkus.deployment.Feature RESTEASY_REACTIVE'
[ERROR]         at io.quarkus.resteasy.reactive.server.deployment.ResteasyReactiveProcessor.buildSetup(ResteasyReactiveProcessor.java:239)

I tried following the contributing guide for the steps, but something didn't go well I guess.

maybe I can be of a better help if a snapshop version is published

[geoand]

I had that as well (it's likely due to build caching - cc @gsmet), but I was able to get over it by cleaning my ~/.m2/repository/io/quarkus directory and built with mvn -Dquickly

[AnastasiiaL]

so I tried cleaning the directory and rebuilding quarkus locally, but that didn't solve the issue.

Basically when I only use the local version I get this error:

[ERROR] Failed to execute goal on project cms-webapp: Could not resolve dependencies for project nl.cms:cms-webapp:jar:1.0.0-SNAPSHOT: The following artifacts could not be resolved: io.quarkus:quarkus-resteasy-reactive-qute:jar:999-SNAPSHOT (absent), io.quarkus:quarkus-resteasy-reactive-jsonb:jar:999-SNAPSHOT (absent): Could not find artifact io.quarkus:quarkus-resteasy-reactive-qute:jar:999-SNAPSHOT -> [Help 1]

then I also enable fetching from the quarkus snapshots repo https://s01.oss.sonatype.org/content/repositories/snapshots and then I get the error above, for the same 3 dependencies.

[geoand]

How did you do the local build?

[AnastasiiaL]

How did you do the local build?

1. softwareupdate --install-rosetta
2. git clone https://github.com/quarkusio/quarkus.git
3. commited your change on top of main
4. cd quarkus
5. export MAVEN_OPTS="-Xmx4g"
6. ./mvnw -Dquickly --> results in BUILD SUCCESS

[gsmet]

@AnastasiiaL build Quarkus with -Prelocations.

Some extensions have been renamed and you are still using the old ones.

[gsmet]

(Sorry we are in the middle of a major change in Quarkus, see https://github.com/quarkusio/quarkus/wiki/Migration-Guide-3.9 for more details)

The easiest way to do a quick test for you is to build with ./mvnw -Dquickly -Prelocations

[AnastasiiaL]

aha, -Prelocations has solved it indeed. Thank you! I am happy to hear I was just missing something important rather than failing to follow the simplest instructions:)

so far the tests are passing in my sample app. I will update you once more when it ran enough times to make any conclusions.

[geoand]

Thanks a lot for your help!

[AnastasiiaL]

I ran it around 30 times - the problem wasn't reproducible anymore. Then I rolled back to use v.3.8.1 - and it failed on the 5th run, so while there's no guarantee when trying to catch a flaky problem - it does look like this fix does the job 👍

[geoand]

Awesome, thanks so much!

[AnastasiiaL]

Thanks for looking into it! Amazing how you pin-pointed the source of it right away:)

[geoand]

Lucky guess :)