Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Unexpected INFO "exception" Log is thrown when I am dropping and creating a schema/tables on Oracle #26228

Closed
pjgg opened this issue Jun 20, 2022 · 11 comments
Closed

Unexpected INFO "exception" Log is thrown when I am dropping and creating a schema/tables on Oracle #26228

pjgg opened this issue Jun 20, 2022 · 11 comments
Labels
area/hibernate-orm Hibernate ORM kind/bug Something isn't working

Comments

@pjgg
Copy link
Contributor

pjgg commented Jun 20, 2022 •
edited
Loading

Describe the bug

Quarkus: 2.9.2.Final

When a Quarkus application that is using quarkus-hibernate-orm-panache extension is dropping and creating an Oracle schema/tables an unexpected INFO log is dropped to the console:

Note: Works well in Mysql or Postgresql

11:47:07,875 INFO  [app] 11:47:06,950 GenerationTarget encountered exception accepting command : Error executing DDL "drop table book cascade constraints" via JDBC Statement: org.hibernate.tool.schema.spi.CommandAcceptanceException: Error executing DDL "drop table book cascade constraints" via JDBC Statement
11:47:07,875 INFO  [app]        at org.hibernate.tool.schema.internal.exec.GenerationTargetToDatabase.accept(GenerationTargetToDatabase.java:67)
11:47:07,875 INFO  [app]        at org.hibernate.tool.schema.internal.SchemaDropperImpl.applySqlString(SchemaDropperImpl.java:387)
11:47:07,876 INFO  [app]        at org.hibernate.tool.schema.internal.SchemaDropperImpl.applySqlStrings(SchemaDropperImpl.java:371)
11:47:07,876 INFO  [app]        at org.hibernate.tool.schema.internal.SchemaDropperImpl.dropFromMetadata(SchemaDropperImpl.java:246)
11:47:07,876 INFO  [app]        at org.hibernate.tool.schema.internal.SchemaDropperImpl.performDrop(SchemaDropperImpl.java:156)
11:47:07,877 INFO  [app]        at org.hibernate.tool.schema.internal.SchemaDropperImpl.doDrop(SchemaDropperImpl.java:128)
11:47:07,877 INFO  [app]        at org.hibernate.tool.schema.internal.SchemaDropperImpl.doDrop(SchemaDropperImpl.java:114)
11:47:07,877 INFO  [app]        at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.performDatabaseAction(SchemaManagementToolCoordinator.java:157)
11:47:07,877 INFO  [app]        at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.process(SchemaManagementToolCoordinator.java:85)
11:47:07,878 INFO  [app]        at org.hibernate.internal.SessionFactoryImpl.<init>(SessionFactoryImpl.java:335)
11:47:07,878 INFO  [app]        at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:74)
11:47:07,878 INFO  [app]        at io.quarkus.hibernate.orm.runtime.FastBootHibernatePersistenceProvider.createEntityManagerFactory(FastBootHibernatePersistenceProvider.java:71)
11:47:07,878 INFO  [app]        at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:80)
11:47:07,879 INFO  [app]        at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:55)
11:47:07,879 INFO  [app]        at io.quarkus.hibernate.orm.runtime.JPAConfig$LazyPersistenceUnit.get(JPAConfig.java:138)
11:47:07,879 INFO  [app]        at io.quarkus.hibernate.orm.runtime.JPAConfig$1.run(JPAConfig.java:54)
11:47:07,879 INFO  [app]        at java.base/java.lang.Thread.run(Thread.java:829)
11:47:07,880 INFO  [app] Caused by: java.sql.SQLSyntaxErrorException: ORA-00942: table or view does not exist

In my opinion, the table book should not be removed if doesn't exist, or at least don't print an "error" stacktrace on the console.

application.properties

quarkus.datasource.db-kind=oracle
quarkus.hibernate-orm.sql-load-script=import.sql
quarkus.hibernate-orm.database.generation=drop-and-create

Expected behavior

No INFO error is logged. Same behavior as other datasources as postgresql

Actual behavior

The following INFO is logged on the console:

11:47:07,873 INFO  [app] __  ____  __  _____   ___  __ ____  ______ 
11:47:07,874 INFO  [app]  --/ __ \/ / / / _ | / _ \/ //_/ / / / __/ 
11:47:07,874 INFO  [app]  -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \   
11:47:07,875 INFO  [app] --\___\_\____/_/ |_/_/|_/_/|_|\____/___/   
11:47:07,875 INFO  [app] 11:47:06,950 GenerationTarget encountered exception accepting command : Error executing DDL "drop table book cascade constraints" via JDBC Statement: org.hibernate.tool.schema.spi.CommandAcceptanceException: Error executing DDL "drop table book cascade constraints" via JDBC Statement
11:47:07,875 INFO  [app]        at org.hibernate.tool.schema.internal.exec.GenerationTargetToDatabase.accept(GenerationTargetToDatabase.java:67)
11:47:07,875 INFO  [app]        at org.hibernate.tool.schema.internal.SchemaDropperImpl.applySqlString(SchemaDropperImpl.java:387)
11:47:07,876 INFO  [app]        at org.hibernate.tool.schema.internal.SchemaDropperImpl.applySqlStrings(SchemaDropperImpl.java:371)
11:47:07,876 INFO  [app]        at org.hibernate.tool.schema.internal.SchemaDropperImpl.dropFromMetadata(SchemaDropperImpl.java:246)
11:47:07,876 INFO  [app]        at org.hibernate.tool.schema.internal.SchemaDropperImpl.performDrop(SchemaDropperImpl.java:156)
11:47:07,877 INFO  [app]        at org.hibernate.tool.schema.internal.SchemaDropperImpl.doDrop(SchemaDropperImpl.java:128)
11:47:07,877 INFO  [app]        at org.hibernate.tool.schema.internal.SchemaDropperImpl.doDrop(SchemaDropperImpl.java:114)
11:47:07,877 INFO  [app]        at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.performDatabaseAction(SchemaManagementToolCoordinator.java:157)
11:47:07,877 INFO  [app]        at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.process(SchemaManagementToolCoordinator.java:85)
11:47:07,878 INFO  [app]        at org.hibernate.internal.SessionFactoryImpl.<init>(SessionFactoryImpl.java:335)
11:47:07,878 INFO  [app]        at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:74)
11:47:07,878 INFO  [app]        at io.quarkus.hibernate.orm.runtime.FastBootHibernatePersistenceProvider.createEntityManagerFactory(FastBootHibernatePersistenceProvider.java:71)
11:47:07,878 INFO  [app]        at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:80)
11:47:07,879 INFO  [app]        at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:55)
11:47:07,879 INFO  [app]        at io.quarkus.hibernate.orm.runtime.JPAConfig$LazyPersistenceUnit.get(JPAConfig.java:138)
11:47:07,879 INFO  [app]        at io.quarkus.hibernate.orm.runtime.JPAConfig$1.run(JPAConfig.java:54)
11:47:07,879 INFO  [app]        at java.base/java.lang.Thread.run(Thread.java:829)
11:47:07,880 INFO  [app] Caused by: java.sql.SQLSyntaxErrorException: ORA-00942: table or view does not exist
11:47:07,880 INFO  [app]        at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:630)
11:47:07,881 INFO  [app]        at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:564)
11:47:07,881 INFO  [app]        at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:1231)
11:47:07,881 INFO  [app]        at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:772)
11:47:07,881 INFO  [app]        at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:299)
11:47:07,882 INFO  [app]        at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:512)
11:47:07,882 INFO  [app]        at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:123)
11:47:07,882 INFO  [app]        at oracle.jdbc.driver.T4CStatement.executeForRows(T4CStatement.java:1200)
11:47:07,882 INFO  [app]        at oracle.jdbc.driver.OracleStatement.executeSQLStatement(OracleStatement.java:1820)
11:47:07,882 INFO  [app]        at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1472)
11:47:07,883 INFO  [app]        at oracle.jdbc.driver.OracleStatement.executeInternal(OracleStatement.java:2505)
11:47:07,883 INFO  [app]        at oracle.jdbc.driver.OracleStatement.execute(OracleStatement.java:2460)
11:47:07,883 INFO  [app]        at oracle.jdbc.driver.OracleStatementWrapper.execute(OracleStatementWrapper.java:328)
11:47:07,883 INFO  [app]        at io.agroal.pool.wrapper.StatementWrapper.execute(StatementWrapper.java:235)
11:47:07,884 INFO  [app]        at org.hibernate.tool.schema.internal.exec.GenerationTargetToDatabase.accept(GenerationTargetToDatabase.java:54)
11:47:07,884 INFO  [app]        ... 16 more
11:47:07,884 INFO  [app] Caused by: Error : 942, Position : 11, Sql = drop table book cascade constraints, OriginalSql = drop table book cascade constraints, Error Msg = ORA-00942: table or view does not exist
11:47:07,884 INFO  [app]        at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:637)
11:47:07,884 INFO  [app]        ... 30 more
11:47:07,885 INFO  [app] 11:47:06,967 GenerationTarget encountered exception accepting command : Error executing DDL "drop sequence hibernate_sequence" via JDBC Statement: org.hibernate.tool.schema.spi.CommandAcceptanceException: Error executing DDL "drop sequence hibernate_sequence" via JDBC Statement
11:47:07,885 INFO  [app]        at org.hibernate.tool.schema.internal.exec.GenerationTargetToDatabase.accept(GenerationTargetToDatabase.java:67)
11:47:07,885 INFO  [app]        at org.hibernate.tool.schema.internal.SchemaDropperImpl.applySqlString(SchemaDropperImpl.java:387)
11:47:07,885 INFO  [app]        at org.hibernate.tool.schema.internal.SchemaDropperImpl.applySqlStrings(SchemaDropperImpl.java:371)
11:47:07,885 INFO  [app]        at org.hibernate.tool.schema.internal.SchemaDropperImpl.dropFromMetadata(SchemaDropperImpl.java:256)
11:47:07,886 INFO  [app]        at org.hibernate.tool.schema.internal.SchemaDropperImpl.performDrop(SchemaDropperImpl.java:156)
11:47:07,886 INFO  [app]        at org.hibernate.tool.schema.internal.SchemaDropperImpl.doDrop(SchemaDropperImpl.java:128)
11:47:07,886 INFO  [app]        at org.hibernate.tool.schema.internal.SchemaDropperImpl.doDrop(SchemaDropperImpl.java:114)
11:47:07,886 INFO  [app]        at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.performDatabaseAction(SchemaManagementToolCoordinator.java:157)
11:47:07,887 INFO  [app]        at org.hibernate.tool.schema.spi.SchemaManagementToolCoordinator.process(SchemaManagementToolCoordinator.java:85)
11:47:07,887 INFO  [app]        at org.hibernate.internal.SessionFactoryImpl.<init>(SessionFactoryImpl.java:335)
11:47:07,887 INFO  [app]        at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:74)
11:47:07,887 INFO  [app]        at io.quarkus.hibernate.orm.runtime.FastBootHibernatePersistenceProvider.createEntityManagerFactory(FastBootHibernatePersistenceProvider.java:71)
11:47:07,887 INFO  [app]        at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:80)
11:47:07,888 INFO  [app]        at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:55)
11:47:07,888 INFO  [app]        at io.quarkus.hibernate.orm.runtime.JPAConfig$LazyPersistenceUnit.get(JPAConfig.java:138)
11:47:07,888 INFO  [app]        at io.quarkus.hibernate.orm.runtime.JPAConfig$1.run(JPAConfig.java:54)
11:47:07,888 INFO  [app]        at java.base/java.lang.Thread.run(Thread.java:829)
11:47:07,888 INFO  [app] Caused by: java.sql.SQLSyntaxErrorException: ORA-02289: sequence does not exist
11:47:07,889 INFO  [app]        at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:630)
11:47:07,889 INFO  [app]        at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:564)
11:47:07,889 INFO  [app]        at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:1231)
11:47:07,889 INFO  [app]        at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:772)
11:47:07,889 INFO  [app]        at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:299)
11:47:07,890 INFO  [app]        at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:512)
11:47:07,892 INFO  [app]        at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:123)
11:47:07,892 INFO  [app]        at oracle.jdbc.driver.T4CStatement.executeForRows(T4CStatement.java:1200)
11:47:07,892 INFO  [app]        at oracle.jdbc.driver.OracleStatement.executeSQLStatement(OracleStatement.java:1820)
11:47:07,893 INFO  [app]        at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1472)
11:47:07,893 INFO  [app]        at oracle.jdbc.driver.OracleStatement.executeInternal(OracleStatement.java:2505)
11:47:07,893 INFO  [app]        at oracle.jdbc.driver.OracleStatement.execute(OracleStatement.java:2460)
11:47:07,893 INFO  [app]        at oracle.jdbc.driver.OracleStatementWrapper.execute(OracleStatementWrapper.java:328)
11:47:07,894 INFO  [app]        at io.agroal.pool.wrapper.StatementWrapper.execute(StatementWrapper.java:235)
11:47:07,895 INFO  [app]        at org.hibernate.tool.schema.internal.exec.GenerationTargetToDatabase.accept(GenerationTargetToDatabase.java:54)
11:47:07,896 INFO  [app]        ... 16 more
11:47:07,896 INFO  [app] Caused by: Error : 2289, Position : 14, Sql = drop sequence hibernate_sequence, OriginalSql = drop sequence hibernate_sequence, Error Msg = ORA-02289: sequence does not exist
11:47:07,897 INFO  [app]        at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:637)
11:47:07,897 INFO  [app]        ... 30 more

How to Reproduce?

  1. git clone --branch feat/oracle_example git@github.com:pjgg/quarkus-test-framework-1.git
  2. mvn clean verify -Dexamples -pl examples/database-oracle -Dit.test=OracleDatabaseIT -Dts.app.log.enable=true

Output of java -version

openjdk 11.0.14 2022-01-18 OpenJDK Runtime Environment Temurin-11.0.14+9 (build 11.0.14+9) OpenJDK 64-Bit Server VM Temurin-11.0.14+9 (build 11.0.14+9, mixed mode)
@pjgg pjgg added the kind/bug Something isn't working label Jun 20, 2022
@geoand geoand added area/hibernate-orm Hibernate ORM and removed triage/needs-triage labels Jun 21, 2022
@quarkus-bot
Copy link

quarkus-bot bot commented Jun 21, 2022

/cc @Sanne, @gsmet, @yrodiere

@yrodiere
Copy link
Member

At first I thought this was a duplicate of #16204, but it seems it's even worse with Oracle: we don't just get a JDBC warning when trying to drop a table that doesn't exist, we get a full-blown exception...

I suspect whatever solution we chose, it will have to be handled in Hibernate ORM. A shame Oracle doesn't support DROP TABLE IF EXISTS, though...

@yrodiere yrodiere mentioned this issue Jun 21, 2022
Closed
@Sanne
Copy link
Member

Sanne commented Jun 21, 2022

Related:

I didn't want us to work on HHH-14889 in ORM5, but for ORM 6 it would be welcome.

@gsmet
Copy link
Member

gsmet commented Jun 21, 2022

Well, improving the situation by using IF EXISTS whenever the dialect supports it would already improve the situation a lot with virtually no cost on our side.
The fact that things would still be bad with Oracle is a separate matter IMO.

@yrodiere
Copy link
Member

Well, improving the situation by using IF EXISTS whenever the dialect supports it would already improve the situation a lot with virtually no cost on our side.

Depends what you mean by "a lot". It would get rid of stack traces, so it would solve this ticket (#26228). We'd still have work on our plate to solve #16204 / HHH-14889.

To clarify, there are two problems:

  1. JDBC warnings being displayed when dropping tables that don't exist... even when using IF EXISTS. That's Hibernate ORM: drop-and-create logs too verbose #16204 / HHH-14889. And changes to Oracle DB won't affect this: it happens for other DBs, such as PostgreSQL.
  2. Stack traces being displayed when dropping tables that don't exist on Oracle DB. That's this ticket, Unexpected INFO "exception" Log is thrown when I am dropping and creating a schema/tables on Oracle #26228. Changes to Oracle DB may remove the stack traces, but we may still have JDBC warnings after that, soo :)

(Also, I'm not sure we can expect people to use the latest version of Oracle, so it will take a few years until we can consider this ticket fixed if we rely exclusively on Oracle adding support for IF EXISTS)

@Sanne
Copy link
Member

Sanne commented Jun 21, 2022

Well, improving the situation by using IF EXISTS whenever the dialect supports it would already improve the situation a lot with virtually no cost on our side.

don't we already do that?

@yrodiere
Copy link
Member

Well, improving the situation by using IF EXISTS whenever the dialect supports it would already improve the situation a lot with virtually no cost on our side.

don't we already do that?

For other databases, yes we do. Though obviously, for Oracle, no dialect supports it at the moment.

https://github.com/hibernate/hibernate-orm/blob/967ede47c0c0728e60a3cea805da6f348b321620/hibernate-core/src/main/java/org/hibernate/tool/schema/internal/StandardTableExporter.java#L237-L251

@gsmet
Copy link
Member

gsmet commented Jun 21, 2022

Ah OK, I thought it was ORM complaining, just ignore me then :).

@Sanne
Copy link
Member

Sanne commented Jun 21, 2022

Right, that's what I thought - you made me doubt my memories :)

@Sanne
Copy link
Member

Sanne commented Jan 19, 2024

I think we should close this one: newer Oracle databases support it, but for the older ones we can't do magic.

Also N.B. it's not a Quarkus bug, Hibernate ORM has been logging such exceptions for about 20 years.. sure that doesn't make it "nice" in any way but there's nothing Quarkus specific here.

@yrodiere
Copy link
Member

Closing. Anyone wanting to get this fixed, please discuss it on https://hibernate.atlassian.net/browse/HHH-14889 or create a separate issue if HHH-14889 is a different problem.

@yrodiere yrodiere closed this as not planned Won't fix, can't repro, duplicate, stale Jan 22, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
area/hibernate-orm Hibernate ORM kind/bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@Sanne @yrodiere @gsmet @pjgg @geoand