search

quarkusio / quarkus

Quarkus: Supersonic Subatomic Java.
https://quarkus.io
Apache License 2.0
13.73k stars 2.67k forks source link

Using database schemas with QuarkusTest logs warnings #25825

Closed Postremus closed 2 years ago

Postremus commented 2 years ago

Describe the bug

I have multiple entities declaring database schemas.

@Entity
@Table(name = "MyEntity", schema = "my_schema")
public class MyEntity {
    @Id
    @GeneratedValue(strategy = GenerationType.SEQUENCE, generator = "id_generator")
    @SequenceGenerator(name = "id_generator", schema = "my_schema", sequenceName = "seq_id", allocationSize = 1, initialValue = 1000)
    @Column(name = "id", unique = true, nullable = false)
    private Long id;
}

This works when I run against a database, where the schemas are already present (e.g. created by liquibase).

I now want to test this code, and wrote a simple test as starting point:

@QuarkusTest
public class MyEntityTest {

    @Inject
    EntityManager em;

    @Test
    @Transactional
    void test() {
        em.persist(new MyEntity());
    }
}

The tests run against a postgresql started by devservices. This test passes since it is only persisting a simple entity.

The schema was not created, according to the logs (see below).

I have following in my application.properties

quarkus.hibernate-orm.database.generation=drop-and-create
quarkus.hibernate-orm.database.generation.create-schemas=true

Expected behavior

Test should should not log warnings.

Actual behavior

[INFO] Running org.acme.MyEntityTest
2022-05-27 09:24:20,739 INFO  [org.jbo.threads] (main) JBoss Threads version 3.4.2.Final
2022-05-27 09:24:21,078 INFO  [org.tes.doc.DockerClientProviderStrategy] (build-12) Loaded org.testcontainers.dockerclient.NpipeSocketClientProviderStrategy from ~/.testcontainers.properties, will try it first
2022-05-27 09:24:21,824 INFO  [org.tes.doc.DockerClientProviderStrategy] (build-12) Found Docker environment with local Npipe socket (npipe:////./pipe/docker_engine)
2022-05-27 09:24:21,826 INFO  [org.tes.DockerClientFactory] (build-12) Docker host IP address is localhost
2022-05-27 09:24:21,856 INFO  [org.tes.DockerClientFactory] (build-12) Connected to docker:
  Server Version: 20.10.11
  API Version: 1.41
  Operating System: Docker Desktop
  Total Memory: 25438 MB
2022-05-27 09:24:21,865 INFO  [org.tes.uti.ImageNameSubstitutor] (build-12) Image name substitution will be performed by: DefaultImageNameSubstitutor (composite of 'ConfigurationFileImageNameSubstitutor' and 'PrefixingImageNameSubstitutor')
2022-05-27 09:24:22,867 INFO  [org.tes.uti.RyukResourceReaper] (build-12) Ryuk started - will monitor and terminate Testcontainers containers on JVM exit
2022-05-27 09:24:22,867 INFO  [org.tes.DockerClientFactory] (build-12) Checking the system...
2022-05-27 09:24:22,868 INFO  [org.tes.DockerClientFactory] (build-12) ?? Docker server version should be at least 1.6.0
2022-05-27 09:24:23,804 INFO  [org.tes.DockerClientFactory] (build-12) ?? Docker environment should have more than 2GB free disk space
2022-05-27 09:24:23,825 INFO  [? .io/.2]] (build-12) Creating container for image: docker.io/postgres:14.2
2022-05-27 09:24:24,275 INFO  [org.tes.uti.RegistryAuthLocator] (build-12) Credential helper/store (docker-credential-desktop) does not have credentials for docker.io
2022-05-27 09:24:24,357 INFO  [? .io/.2]] (build-12) Container docker.io/postgres:14.2 is starting: 4ac5d8fc02fe1d8041234ad3b3f04c4772f2eed4dbdb833bf6588a04a5508013
2022-05-27 09:24:26,035 INFO  [? .io/.2]] (build-12) Container docker.io/postgres:14.2 started in PT2.2205839S
2022-05-27 09:24:26,035 INFO  [io.qua.dev.pos.dep.PostgresqlDevServicesProcessor] (build-12) Dev Services for PostgreSQL started.
2022-05-27 09:24:26,036 INFO  [io.qua.dat.dep.dev.DevServicesDatasourceProcessor] (build-12) Dev Services for the default datasource (postgresql) started.
2022-05-27 09:24:26,793 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2022-05-27 09:24:26,793 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) schema "my_schema" does not exist, skipping
2022-05-27 09:24:26,794 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2022-05-27 09:24:26,794 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) schema "my_schema" does not exist, skipping
2022-05-27 09:24:26,797 WARN  [org.hib.too.sch.int.ExceptionHandlerLoggedImpl] (JPA Startup Thread: <default>) GenerationTarget encountered exception accepting command : Error executing DDL "drop schema my_schema" via JDBC Statement: org.hibernate.tool.schema.spi.CommandAccepta
nceException: Error executing DDL "drop schema my_schema" via JDBC Statement
        at org.hibernate.tool.schema.internal.exec.GenerationTargetToDatabase.accept(GenerationTargetToDatabase.java:67)
        at org.hibernate.tool.schema.internal.SchemaDropperImpl.applySqlString(SchemaDropperImpl.java:387)
        at org.hibernate.tool.schema.internal.SchemaDropperImpl.applySqlStrings(SchemaDropperImpl.java:371)
        at org.hibernate.tool.schema.internal.SchemaDropperImpl.dropFromMetadata(SchemaDropperImpl.java:288)
        at org.hibernate.tool.schema.internal.SchemaDropperImpl.performDrop(SchemaDropperImpl.java:156)
        at org.hibernate.tool.schema.internal.SchemaDropperImpl.doDrop(SchemaDropperImpl.java:128)
        at org.hibernate.tool.schema.internal.SchemaDropperImpl.doDrop(SchemaDropperImpl.java:114)
        at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.performDatabaseAction(SchemaManagementToolCoordinator.java:157)
        at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.process(SchemaManagementToolCoordinator.java:85)
        at org.hibernate.internal.SessionFactoryImpl.<init>(SessionFactoryImpl.java:335)
        at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:74)
        at io.quarkus.hibernate.orm.runtime.FastBootHibernatePersistenceProvider.createEntityManagerFactory(FastBootHibernatePersistenceProvider.java:71)
        at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:80)
        at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:55)
        at io.quarkus.hibernate.orm.runtime.JPAConfig$LazyPersistenceUnit.get(JPAConfig.java:138)
        at io.quarkus.hibernate.orm.runtime.JPAConfig$1.run(JPAConfig.java:54)
        at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: org.postgresql.util.PSQLException: ERROR: schema "my_schema" does not exist
        at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2675)
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2365)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:355)
        at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:490)
        at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:408)
        at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:329)
        at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:315)
        at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:291)
        at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:286)
        at io.agroal.pool.wrapper.StatementWrapper.execute(StatementWrapper.java:235)
        at org.hibernate.tool.schema.internal.exec.GenerationTargetToDatabase.accept(GenerationTargetToDatabase.java:54)
        ... 16 more

2022-05-27 09:24:26,819 INFO  [io.quarkus] (main) orm-schema-creation 1.0.0-SNAPSHOT on JVM (powered by Quarkus 2.9.2.Final) started in 6.553s.
2022-05-27 09:24:26,820 INFO  [io.quarkus] (main) Profile test activated.
2022-05-27 09:24:26,820 INFO  [io.quarkus] (main) Installed features: [agroal, cdi, hibernate-orm, jdbc-postgresql, narayana-jta, smallrye-context-propagation]
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 8.489 s - in org.acme.MyEntityTest

How to Reproduce?

Reproducer: orm-schema-creation.zip

  1. mvn clean test
  2. warnings from above appear when running the tests

Output of uname -a or ver

Microsoft Windows [Version 10.0.19044.1706]

Output of java -version

openjdk 18.0.1 2022-04-19 OpenJDK Runtime Environment Temurin-18.0.1+10 (build 18.0.1+10) OpenJDK 64-Bit Server VM Temurin-18.0.1+10 (build 18.0.1+10, mixed mode, sharing)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.9.2.Final

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

Apache Maven 3.8.4 (9b656c72d54e5bacbed989b64718c159fe39b537) Maven home: C:\eclipse\tools\java\maven Java version: 18.0.1, vendor: Eclipse Adoptium, runtime: C:\eclipse\tools\java\18 Default locale: de_DE, platform encoding: UTF-8 OS name: "windows 10", version: "10.0", arch: "amd64", family: "windows"

Additional information

No response

quarkus-bot[bot] commented 2 years ago

/cc @DavideD, @Sanne, @gavinking, @gsmet, @mswatosh, @yrodiere

yrodiere commented 2 years ago

You instructed Hibernate ORM to "drop and create" the schema, and the schema did not exist. So Hibernate ORM tried to drop the schema, it failed, and Hibernate ORM warned you that the dropping failed. Then it went on an created the schema, and everything should work fine,

We're aware these log messages are confusing, and this has already been reported here: https://github.com/quarkusio/quarkus/issues/16204

Please continue the conversation on that other ticket, or add a message here if you think yours is a different problem.

Closing as duplicate.

yrodiere commented 2 years ago

Duplicates #16204