search

quarkusio / quarkus

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

Hibernate ORM: `drop-and-create` logs too verbose #16204

Closed FroMage closed 3 months ago

FroMage commented 3 years ago

In DEV mode, I just got those logs:

2021-04-02 09:40:02,743 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (Quarkus Main Thread) SQL Warning Code: 0, SQLState: 00000
2021-04-02 09:40:02,744 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (Quarkus Main Thread) relation "orders" does not exist, skipping
2021-04-02 09:40:02,744 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (Quarkus Main Thread) SQL Warning Code: 0, SQLState: 00000
2021-04-02 09:40:02,745 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (Quarkus Main Thread) table "customers" does not exist, skipping
2021-04-02 09:40:02,745 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (Quarkus Main Thread) SQL Warning Code: 0, SQLState: 00000
2021-04-02 09:40:02,745 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (Quarkus Main Thread) table "orders" does not exist, skipping
2021-04-02 09:40:02,746 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (Quarkus Main Thread) SQL Warning Code: 0, SQLState: 00000
2021-04-02 09:40:02,746 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (Quarkus Main Thread) sequence "hibernate_sequence" does not exist, skipping

Due to this config:

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

Given that they're not real issues, and we know about them, is there any way we can filter them out?

CC @Sanne @yrodiere ?

quarkus-bot[bot] commented 3 years ago

/cc @Sanne, @gsmet, @yrodiere

Sanne commented 3 years ago

I guess we could filter them, but I'm not sure about it being a good idea. It seems the ones you got are harmless, but what if you had a more serious SQL exception?

Ideally ORM could be improved to have an advanced dictionary to grade the severity of each such case, but unless it gets contributed I'm afraid we have more pressing things to fix.

gavinking commented 3 years ago

Agreed. We really don't have a good way to know that the warning is completely harmless.

FroMage commented 3 years ago

Don't they follow an obvious pattern? If we know what tables we create, I mean.

gsmet commented 3 years ago

Which database is it? Is it one for which we use IF EXISTS?

Sanne commented 3 years ago

Which database is it? Is it one for which we use IF EXISTS?

agreed this is the better direction to approach the issue.

FroMage commented 3 years ago

Pretty sure it's postgres. Not sure if you use IF EXISTS.

FroMage commented 3 years ago

So, my app startup is now:

__  ____  __  _____   ___  __ ____  ______ 
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/ 
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \   
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/   
2021-11-05 15:04:38,351 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,352 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) relation "album" does not exist, skipping
2021-11-05 15:04:38,353 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,353 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) relation "album" does not exist, skipping
2021-11-05 15:04:38,354 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,354 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) relation "album" does not exist, skipping
2021-11-05 15:04:38,355 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,355 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) relation "album" does not exist, skipping
2021-11-05 15:04:38,356 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,357 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) relation "alert" does not exist, skipping
2021-11-05 15:04:38,357 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,358 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) relation "badge" does not exist, skipping
2021-11-05 15:04:38,359 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,359 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) relation "like_table" does not exist, skipping
2021-11-05 15:04:38,360 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,360 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) relation "like_table" does not exist, skipping
2021-11-05 15:04:38,361 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,361 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) relation "like_table" does not exist, skipping
2021-11-05 15:04:38,362 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,362 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) relation "personorgroup" does not exist, skipping
2021-11-05 15:04:38,363 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,363 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) relation "personorgroup" does not exist, skipping
2021-11-05 15:04:38,364 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,365 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) relation "personorgroup" does not exist, skipping
2021-11-05 15:04:38,365 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,366 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) relation "reputationgain" does not exist, skipping
2021-11-05 15:04:38,366 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,366 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) relation "reputationgain" does not exist, skipping
2021-11-05 15:04:38,367 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,367 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) relation "reputationgain" does not exist, skipping
2021-11-05 15:04:38,368 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,368 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) relation "vote" does not exist, skipping
2021-11-05 15:04:38,369 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,369 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) relation "vote" does not exist, skipping
2021-11-05 15:04:38,370 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,370 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) relation "vote" does not exist, skipping
2021-11-05 15:04:38,371 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,371 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) table "album" does not exist, skipping
2021-11-05 15:04:38,371 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,372 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) table "alert" does not exist, skipping
2021-11-05 15:04:38,372 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,372 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) table "badge" does not exist, skipping
2021-11-05 15:04:38,373 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,373 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) table "like_table" does not exist, skipping
2021-11-05 15:04:38,374 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,374 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) table "personorgroup" does not exist, skipping
2021-11-05 15:04:38,375 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,375 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) table "reputationgain" does not exist, skipping
2021-11-05 15:04:38,376 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,376 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) table "setting" does not exist, skipping
2021-11-05 15:04:38,376 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,377 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) table "user_table" does not exist, skipping
2021-11-05 15:04:38,377 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,377 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) table "vote" does not exist, skipping
2021-11-05 15:04:38,378 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Warning Code: 0, SQLState: 00000
2021-11-05 15:04:38,378 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) sequence "hibernate_sequence" does not exist, skipping
2021-11-05 15:04:39,851 INFO  [io.quarkus] (Quarkus Main Thread) aviouf 1.0.0-SNAPSHOT on JVM (powered by Quarkus 999-SNAPSHOT) started in 7.574s. Listening on: http://localhost:8080
2021-11-05 15:04:39,852 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2021-11-05 15:04:39,852 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [agroal, cdi, hibernate-orm, hibernate-orm-panache, hibernate-validator, jdbc-postgresql, mailer, narayana-jta, qute, reactive-routes, resteasy-reactive, resteasy-reactive-qute, security, smallrye-context-propagation, smallrye-jwt, vertx, vixen]

As you can see, it's mostly bullshit. I wish I could filter it out but it doesn't seem obvious how. I've set a breakpoint in where it's printed and there:

Daemon Thread [JPA Startup Thread: <default>] (Suspended)   
    owns: JPAConfig$LazyPersistenceUnit  (id=16987) 
    SqlExceptionHelper$StandardWarningHandler.logWarning(String, String) line: 230  
    SqlExceptionHelper$StandardWarningHandler(SqlExceptionHelper$WarningHandlerLoggingSupport).handleWarning(SQLWarning) line: 186  
    SqlExceptionHelper.walkWarnings(SQLWarning, SqlExceptionHelper$WarningHandler) line: 256    
    SqlExceptionHelper.handleAndClearWarnings(Statement, SqlExceptionHelper$WarningHandler) line: 322   
    SqlExceptionHelper.logAndClearWarnings(Statement) line: 273 
    GenerationTargetToDatabase.accept(String) line: 59  
    SchemaDropperImpl.applySqlString(String, Formatter, ExecutionOptions, GenerationTarget...) line: 375    
    SchemaDropperImpl.applySqlStrings(String[], Formatter, ExecutionOptions, GenerationTarget...) line: 359 
    SchemaDropperImpl.applyConstraintDropping(Namespace, Metadata, Formatter, ExecutionOptions, GenerationTarget...) line: 331  
    SchemaDropperImpl.dropFromMetadata(Metadata, ExecutionOptions, Dialect, Formatter, GenerationTarget...) line: 230   
    SchemaDropperImpl.performDrop(Metadata, ExecutionOptions, Dialect, SourceDescriptor, GenerationTarget...) line: 154 
    SchemaDropperImpl.doDrop(Metadata, ExecutionOptions, Dialect, SourceDescriptor, GenerationTarget...) line: 126  
    SchemaDropperImpl.doDrop(Metadata, ExecutionOptions, SourceDescriptor, TargetDescriptor) line: 112  
    SchemaManagementToolCoordinator.performDatabaseAction(Action, Metadata, SchemaManagementTool, ServiceRegistry, ExecutionOptions) line: 153  
    SchemaManagementToolCoordinator.process(Metadata, ServiceRegistry, Map, DelayedDropRegistry) line: 81   
    SessionFactoryImpl.<init>(MetadataImplementor, SessionFactoryOptions, QueryPlanCache$QueryPlanCreator) line: 327    
    FastBootEntityManagerFactoryBuilder.build() line: 74    
    FastBootHibernatePersistenceProvider.createEntityManagerFactory(String, Map) line: 67   
    Persistence.createEntityManagerFactory(String, Map) line: 80    
    Persistence.createEntityManagerFactory(String) line: 55 
    JPAConfig$LazyPersistenceUnit.get() line: 149   
    JPAConfig$1.run() line: 58  
    Thread.run() line: 829

I guess if we could set a threadlocal indicating we're in SchemaDropperImpl.doDrop with a setting of drop-and-create and perhaps in DEV mode, then I could filter these out, but it would need more than LogFilterBuildItem which can only match on prefixes, not on logic. I could also filter it out from org.hibernate.engine.jdbc.spi.SqlExceptionHelper.STANDARD_WARNING_HANDLER if I could override the damn handler, but I don't see how.

We really have to fix this stuff, it's a very poor startup experience.

yrodiere commented 2 years ago

Note it's even worse with some databases, e.g. Oracle: it seems we display a full stack trace... See #26228

Maybe we should have a look at how to fix this in Hibernate ORM 6.x, with a list of error codes we can safely ignore in exceptions/JDBC warnings, but that should be only in the context of schema dropping, and that will probably require some disruptive internal changes...

mklueh commented 1 year ago

Is it possible to suppress these logs? Intellij always jumps from the "Run" tab to the "build" tab when this happens and you need to navigate back to see your test results

FroMage commented 1 year ago

FYI @yrodiere , Renarde took this bold build step:

    @BuildStep
    void removeHibernateLogging(LaunchModeBuildItem launchMode,
            BuildProducer<LogCleanupFilterBuildItem> logFilters) {
        if (launchMode.getLaunchMode().isDevOrTest()) {
            // FIXME: this is too broad, but waits for https://github.com/quarkusio/quarkus/issues/16204 to be fixed
            logFilters
                    .produce(new LogCleanupFilterBuildItem("org.hibernate.engine.jdbc.spi.SqlExceptionHelper",
                            "SQL Warning Code: 0, SQLState: 00000",
                            "relation \"",
                            "table \"",
                            "sequence \""));
        }
    }

And I've never felt this problem again :)

FroMage commented 8 months ago

@gavinking any change you can make magic happen?

trym-moeller commented 8 months ago

Another input for this issue:

I have a quarkus microservice using a h2 db (in test) and I have configured a default scheme

and in test I have configured quarkus/hibernate to create schema and tables

When I run tests I see logs of warning level regarding an unknown schema (when dropping tables).

Can I do anything so hibernate orm does not try to delete tables in a non-existing schema?

Thanks for any input.

Best regards Trym

Stracktrace:

2024-02-21 08:10:05,546 WARN  [org.hib.too.sch.int.ExceptionHandlerLoggedImpl] (JPA Startup Thread) GenerationTarget encountered exception accepting command : Error executing DDL "drop table if exists my-schema.my-table cascade " via JDBC [Schema "my-schema" not found;]: org.hibernate.tool.schema.spi.CommandAcceptanceException: Error executing DDL "drop table if exists my-schema.my-table cascade " via JDBC [Schema "my-schema" not found;]
    at org.hibernate.tool.schema.internal.exec.GenerationTargetToDatabase.accept(GenerationTargetToDatabase.java:94)
    at org.hibernate.tool.schema.internal.Helper.applySqlString(Helper.java:233)
    at org.hibernate.tool.schema.internal.Helper.applySqlStrings(Helper.java:217)
    at org.hibernate.tool.schema.internal.SchemaDropperImpl.dropTables(SchemaDropperImpl.java:362)
    at org.hibernate.tool.schema.internal.SchemaDropperImpl.dropConstraintsTablesSequences(SchemaDropperImpl.java:253)
    at org.hibernate.tool.schema.internal.SchemaDropperImpl.dropFromMetadata(SchemaDropperImpl.java:215)
    at org.hibernate.tool.schema.internal.SchemaDropperImpl.performDrop(SchemaDropperImpl.java:185)
    at org.hibernate.tool.schema.internal.SchemaDropperImpl.doDrop(SchemaDropperImpl.java:155)
    at org.hibernate.tool.schema.internal.SchemaDropperImpl.doDrop(SchemaDropperImpl.java:115)
    at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.performDatabaseAction(SchemaManagementToolCoordinator.java:242)
    at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.lambda$process$5(SchemaManagementToolCoordinator.java:143)
    at java.base/java.util.HashMap.forEach(HashMap.java:1429)
    at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.process(SchemaManagementToolCoordinator.java:140)
    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:293)
    at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:84)
    at io.quarkus.hibernate.orm.runtime.FastBootHibernatePersistenceProvider.createEntityManagerFactory(FastBootHibernatePersistenceProvider.java:74)
    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:156)
    at io.quarkus.hibernate.orm.runtime.JPAConfig$1.run(JPAConfig.java:64)
    at java.base/java.lang.Thread.run(Thread.java:1583)

Caused by: org.h2.jdbc.JdbcSQLSyntaxErrorException: Schema "my-schema" not found; SQL statement:
drop table if exists my-schema.my-table cascade  [90079-224]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:644)
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:489)
    at org.h2.message.DbException.get(DbException.java:223)
    at org.h2.message.DbException.get(DbException.java:199)
    at org.h2.command.Parser.getSchema(Parser.java:944)
    at org.h2.command.Parser.getSchema(Parser.java:950)
    at org.h2.command.Parser.parseDrop(Parser.java:2114)
    at org.h2.command.Parser.parsePrepared(Parser.java:679)
    at org.h2.command.Parser.parse(Parser.java:592)
    at org.h2.command.Parser.parse(Parser.java:564)
    at org.h2.command.Parser.prepareCommand(Parser.java:483)
    at org.h2.engine.SessionLocal.prepareLocal(SessionLocal.java:639)
    at org.h2.engine.SessionLocal.prepareCommand(SessionLocal.java:559)
    at org.h2.jdbc.JdbcConnection.prepareCommand(JdbcConnection.java:1166)
    at org.h2.jdbc.JdbcStatement.executeInternal(JdbcStatement.java:245)
    at org.h2.jdbc.JdbcStatement.execute(JdbcStatement.java:231)
    at io.agroal.pool.wrapper.StatementWrapper.execute(StatementWrapper.java:235)
    at org.hibernate.tool.schema.internal.exec.GenerationTargetToDatabase.accept(GenerationTargetToDatabase.java:80)
    ... 22 more
gavinking commented 5 months ago

@FroMage

Pretty sure it's postgres. Not sure if you use IF EXISTS.

We do (of course) use IF EXISTS on Postgres. But I suppose Postgres sends us a warning anyway.

Maybe we should have a look at how to fix this in Hibernate ORM 6.x,

This has annoyed me no end, but I don't see an obvious reasonable way to fix it. I don't think we can just ignore errors that occur during schema export, not even while dropping.

with a list of error codes we can safely ignore in exceptions/JDBC warnings,

I'm skeptical that such error codes exist. If you look at what we log for Postgres, it's:

SQL Warning Code: 0, SQLState: 00000

So there's no useful information there.

We also get the message:

 relation "book_aliases" does not exist, skipping

so in principle we could filter based on that English text, but that's quite fragile.

@trym-moeller

Can I do anything so hibernate orm does not try to delete tables in a non-existing schema?

Well, yes, of course you can: configure it to only-export, instead of first dropping.

Hell, with SchemaManager, you can even write your own code to decide when to drop. For example, you could check if the schema exists, and if it does not, don't drop anything.

So this is quite easily-solved on your end.

gavinking commented 5 months ago

If someone really wants this fixed, they could write code to check with the JDBC metadata (or information_schema) that the table exists before sending the drop statement.

gavinking commented 5 months ago

If someone really wants this fixed, they could write code to check with the JDBC metadata (or information_schema) that the table exists before sending the drop statement.

Actually, this is not terribly hard, since AbstractSchemaMigrator already shows how to do it. (There are APIs.) So StandardTableExporter could do it the same way.

omasseau commented 4 months ago

This is quite annoying when you start developing in Quarkus. It makes you think you have configured something wrong, and you lose a lot of time trying to figure out what may be wrong. Having a bad first experience like this with a framework is not really good (especially for junior developers).

yrodiere commented 4 months ago

I'm skeptical that such error codes exist. If you look at what we log for Postgres, it's:

SQL Warning Code: 0, SQLState: 00000

So there's no useful information there.

I just looked at what this SQLState is... and it turns out it's clearly defined. From the javadoc of java.sql.SQLWarning#SQLWarning(java.lang.String, java.lang.String):

SQLState – an XOPEN or SQL:2003 code identifying the warning

In Postgres at least, this code is not just set to 00000 all the time, it's actually retrieved from the server response.

And from what I can read here, 00000 actually indicates "successful completion", so... it could be ignored? And actually any code starting with 00 is technically a "success" so could be ignored. EDIT: Or at least we could adapt the logging level based on the first two digits: 00 => DEBUG/TRACE, 01 -> WARNING, 02 ("no data") => ???, anything else -> ERROR

Question is, can we actually rely on these codes being set correctly by JDBC drivers. But if they are, and for postgres it seems they are, we can probably do something.

WDYT @gavinking? Am I misinterpreting something? I just learned about this "standard"...

gavinking commented 4 months ago

I mean:

So I don't see how a warning can be 00, unless it's just .... wrong, and therefore untrustworthy.

I already outlined a way to solve this by simply not sending the DROP statement in the first place, so I don't think we should do a doubtfully-correct fix when a more correct fix is quite straightforward.

On the other hand, if nobody can be bothered to implement the straightforward fix, then obviously this is a very low-priority problem and we should quit wasting time arguing over it.

yrodiere commented 4 months ago

I already outlined a way to solve this by simply not sending the DROP statement in the first place, so I don't think we should do a doubtfully-correct fix when a more correct fix is quite straightforward. [...] On the other hand, if nobody can be bothered to implement the straightforward fix, [...]

It's straightforward to implement, but this has obvious downsides. We have several pending bug reports about very bad performance when retrieving metadata from the database on large models -- we're talking about dozens of minutes.

So sure it's one way, but no it's not a silver bullet. Hence this discussion.

we should quit wasting time arguing over it.

My point is not -- or rather, wasn't -- to argue, but to propose a workable solution that wouldn't cost much to implement. I suppose we can indeed call that a waste of time if it doesn't lead to any actual patch.

So I don't see how a warning can be 00, unless it's just .... wrong, and therefore untrustworthy.

In the specific case of the PostgresQL JDBC driver, these codes seem trustworthy -- as in, they match what the DB returned. It's simply that the driver shoves all non-error messages into warnings.

To be fair, it's not like JDBC has a very precise mapping with these SQL states: there's success, warning, error, "no data" (whatever that means), but on the JDBC side we have only warning and exception.

We can certainly report the problem to the postgresql JDBC driver, and ask them to filter out non-warnings properly. But I'm not very confident this will lead somewhere, and I suspect it will take time (though I may be wrong).

Personally I think implementing a few conditions in ORM's SQLHelper, at least for databases known to have reliable SQLStates, to log on a different level depending on the SQLState, would make sense. It wouldn't be the first time we work around a questionable behavior in a JDBC driver for convenience.

yrodiere commented 4 months ago

On the other hand, if nobody can be bothered to implement the straightforward fix, then obviously this is a very low-priority problem and we should quit wasting time arguing over it.

Here, somebody could be bothered: https://github.com/hibernate/hibernate-orm/pull/8595 , https://hibernate.atlassian.net/browse/HHH-18296

FroMage commented 4 months ago

This sounds great, @yrodiere :)

yrodiere commented 4 months ago

FWIW I also reported the issue to pg-jdbc: https://github.com/pgjdbc/pgjdbc/issues/3300

This might be useful if my PR doesn't get merged (and right now, that seems to be the most likely outcome).

davecramer commented 4 months ago

The warning comes from the server. I don't think it's the job of the driver to filter out warnings.

yrodiere commented 4 months ago

The warning comes from the server. I don't think it's the job of the driver to filter out warnings.

My point is it's not a warning, since the SQL state starts with 00. Warnings have an SQL state starting with 01.

And if you think it's not the job of the driver to filter out any message, well, @gavinking thinks it's not the job of Hibernate ORM either, so I guess it will be the application programmer's responsibility.

davecramer commented 4 months ago

So after looking at this some more, I have to agree. Not sure why this is a new problem ?

yrodiere commented 4 months ago

Thanks you so much, that's a nice ending to a bad day 🙂

I don't think the problem is very new, since this was reported in 2021... It just took this long to get prioritized and forwarded after the root cause was identified.

Also, Hibernate ORM has been pushing users to newer db/dialect versions more aggressively lately, so maybe most Hibernate ORM users were using an old dialect before? That does result in far worse logs with large stacktraces, but completely unrelated to pgjdbc. Which would explain why the problem in pgjdbc wasn't noticed by Hibernate ORM users, at least.

yrodiere commented 4 months ago

So, recap of the day:

So https://hibernate.atlassian.net/browse/HHH-18296 will be fixed in ORM 6.6 and this issue will be fixed as soon as Quarkus upgrades to that version (see #41359)

Thanks everyone!

FroMage commented 4 months ago

Sounds great, thanks everyone :)