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.

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

SQL initialization with "data.sql" comes too late if using hibernate DDL auto as well #1006

Closed
mihkels opened this issue May 30, 2014 · 13 comments
Assignees
Labels
type: bug A general bug
Milestone

Comments

@mihkels
Copy link

mihkels commented May 30, 2014

JVM:

java version "1.8.0_05"
Java(TM) SE Runtime Environment (build 1.8.0_05-b13)
Java HotSpot(TM) 64-Bit Server VM (build 25.5-b02, mixed mode)

Spring Boot:

 <parent>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-parent</artifactId>
        <version>1.1.0.M2</version>
    </parent>

    <dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-data-jpa</artifactId>
        </dependency>
        <dependency>
            <groupId>org.projectlombok</groupId>
            <artifactId>lombok</artifactId>
            <version>1.12.6</version>
        </dependency>
        <dependency>
            <groupId>org.hsqldb</groupId>
            <artifactId>hsqldb</artifactId>
            <scope>runtime</scope>
        </dependency>
    </dependencies>

Spring Boot 1.1.0.M2 fails to create HSQLDB in memory database tables and in boot up log there are these line:

2014-05-30 19:11:44.625  INFO 10092 --- [           main] o.h.h.i.ast.ASTQueryTranslatorFactory    : HHH000397: Using ASTQueryTranslatorFactory
2014-05-30 19:11:44.631  WARN 10092 --- [           main] org.hibernate.cfg.SettingsFactory        : Unrecognized value for "hibernate.hbm2ddl.auto": none

For that reason loading in data from data.sql fails with following exception:

2014-05-30 19:11:46.725 ERROR 10092 --- [           main] o.s.boot.SpringApplication               : Application startup failed

org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'org.springframework.boot.autoconfigure.jdbc.DataSourceAutoConfiguration': Invocation of init method failed; nested exception is org.springframework.jdbc.datasource.init.ScriptStatementFailedException: Failed to execute SQL script statement at line 1 of resource URL [file:/C:/projects/personal/sport-store/target/classes/data.sql]: INSERT INTO category (id, name) VALUES (1, 'Watersports'); nested exception is java.sql.SQLSyntaxErrorException: user lacks privilege or object not found: CATEGORY
    at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor.postProcessBeforeInitialization(InitDestroyAnnotationBeanPostProcessor.java:136)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsBeforeInitialization(AbstractAutowireCapableBeanFactory.java:407)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1545)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:539)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:475)
    at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:304)
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:228)
    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:300)
    at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:195)
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:703)
    at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:760)
    at org.springframework.context.support.AbstractApplicationContext.__refresh(AbstractApplicationContext.java:482)
    at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java)
    at org.springframework.boot.context.embedded.EmbeddedWebApplicationContext.refresh(EmbeddedWebApplicationContext.java:120)
    at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:683)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:313)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:944)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:933)
    at com.selgal.sportstore.Application.main(Application.java:13)
Caused by: org.springframework.jdbc.datasource.init.ScriptStatementFailedException: Failed to execute SQL script statement at line 1 of resource URL [file:/C:/projects/personal/sport-store/target/classes/data.sql]: INSERT INTO category (id, name) VALUES (1, 'Watersports'); nested exception is java.sql.SQLSyntaxErrorException: user lacks privilege or object not found: CATEGORY
    at org.springframework.jdbc.datasource.init.ScriptUtils.executeSqlScript(ScriptUtils.java:474)
    at org.springframework.jdbc.datasource.init.ResourceDatabasePopulator.populate(ResourceDatabasePopulator.java:208)
    at org.springframework.jdbc.datasource.init.DatabasePopulatorUtils.execute(DatabasePopulatorUtils.java:49)
    at org.springframework.boot.autoconfigure.jdbc.DataSourceAutoConfiguration.initialize(DataSourceAutoConfiguration.java:115)
    at sun.reflect.GeneratedMethodAccessor240.invoke(Unknown Source)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleElement.invoke(InitDestroyAnnotationBeanPostProcessor.java:349)
    at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleMetadata.invokeInitMethods(InitDestroyAnnotationBeanPostProcessor.java:300)
    at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor.postProcessBeforeInitialization(InitDestroyAnnotationBeanPostProcessor.java:133)
    ... 18 common frames omitted
Caused by: java.sql.SQLSyntaxErrorException: user lacks privilege or object not found: CATEGORY
    at org.hsqldb.jdbc.JDBCUtil.sqlException(Unknown Source)
    at org.hsqldb.jdbc.JDBCUtil.sqlException(Unknown Source)
    at org.hsqldb.jdbc.JDBCStatement.fetchResult(Unknown Source)
    at org.hsqldb.jdbc.JDBCStatement.execute(Unknown Source)
    at org.springframework.jdbc.datasource.init.ScriptUtils.executeSqlScript(ScriptUtils.java:459)
    ... 26 common frames omitted
Caused by: org.hsqldb.HsqlException: user lacks privilege or object not found: CATEGORY
    at org.hsqldb.error.Error.error(Unknown Source)
    at org.hsqldb.error.Error.error(Unknown Source)
    at org.hsqldb.SchemaManager.getTable(Unknown Source)
    at org.hsqldb.ParserDQL.readTableName(Unknown Source)
    at org.hsqldb.ParserDQL.readRangeVariableForDataChange(Unknown Source)
    at org.hsqldb.ParserDML.compileInsertStatement(Unknown Source)
    at org.hsqldb.ParserCommand.compilePart(Unknown Source)
    at org.hsqldb.ParserCommand.compileStatements(Unknown Source)
    at org.hsqldb.Session.executeDirectStatement(Unknown Source)
    at org.hsqldb.Session.execute(Unknown Source)
    ... 29 common frames omitted

Tested also with version 1.0.2.RELEASE and everything works as expected tables are created and data.sql is loaded in without any issues.

@dsyer
Copy link
Member

dsyer commented May 30, 2014

So what did we do wrong? Is the Hibernate property name fat-fingered?

@mihkels
Copy link
Author

mihkels commented May 30, 2014

No I did not override hibernate.properties

The configuration looks like this:

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.EnableAutoConfiguration;
import org.springframework.context.annotation.ComponentScan;
import org.springframework.context.annotation.Configuration;

@Configuration
@EnableAutoConfiguration
@ComponentScan
public class Application {
    public static void main (String[] args) {
        SpringApplication.run(Application.class);
    }
}

Hibernate part in1.0.2.RELEASE:

2014-05-30 20:07:28.988  INFO 6500 --- [           main] org.hibernate.Version                    : HHH000412: Hibernate Core {4.3.1.Final}
2014-05-30 20:07:28.992  INFO 6500 --- [           main] org.hibernate.cfg.Environment            : HHH000206: hibernate.properties not found
2014-05-30 20:07:28.994  INFO 6500 --- [           main] org.hibernate.cfg.Environment            : HHH000021: Bytecode provider name : javassist
2014-05-30 20:07:29.141  INFO 6500 --- [           main] o.hibernate.annotations.common.Version   : HCANN000001: Hibernate Commons Annotations {4.0.4.Final}
2014-05-30 20:07:29.327  INFO 6500 --- [           main] org.hibernate.dialect.Dialect            : HHH000400: Using dialect: org.hibernate.dialect.HSQLDialect
2014-05-30 20:07:29.422  INFO 6500 --- [           main] o.h.h.i.ast.ASTQueryTranslatorFactory    : HHH000397: Using ASTQueryTranslatorFactory
2014-05-30 20:07:29.593  INFO 6500 --- [           main] org.hibernate.tool.hbm2ddl.SchemaExport  : HHH000227: Running hbm2ddl schema export
Hibernate: alter table product drop constraint FK_rlaghtegr0yx2c1q1s6nkqjlh
2014-05-30 20:07:29.595 ERROR 6500 --- [           main] org.hibernate.tool.hbm2ddl.SchemaExport  : HHH000389: Unsuccessful: alter table product drop constraint FK_rlaghtegr0yx2c1q1s6nkqjlh
2014-05-30 20:07:29.595 ERROR 6500 --- [           main] org.hibernate.tool.hbm2ddl.SchemaExport  : user lacks privilege or object not found: PUBLIC.PRODUCT
Hibernate: drop table category if exists
Hibernate: drop table product if exists

Hibernate part in 1.1.0.M2:

2014-05-30 20:10:32.274  INFO 1900 --- [           main] org.hibernate.Version                    : HHH000412: Hibernate Core {4.3.1.Final}
2014-05-30 20:10:32.275  INFO 1900 --- [           main] org.hibernate.cfg.Environment            : HHH000206: hibernate.properties not found
2014-05-30 20:10:32.276  INFO 1900 --- [           main] org.hibernate.cfg.Environment            : HHH000021: Bytecode provider name : javassist
2014-05-30 20:10:32.412  INFO 1900 --- [           main] o.hibernate.annotations.common.Version   : HCANN000001: Hibernate Commons Annotations {4.0.4.Final}
2014-05-30 20:10:32.461  INFO 1900 --- [           main] org.hibernate.dialect.Dialect            : HHH000400: Using dialect: org.hibernate.dialect.HSQLDialect
2014-05-30 20:10:32.554  INFO 1900 --- [           main] o.h.h.i.ast.ASTQueryTranslatorFactory    : HHH000397: Using ASTQueryTranslatorFactory
2014-05-30 20:10:32.557  WARN 1900 --- [           main] org.hibernate.cfg.SettingsFactory        : Unrecognized value for "hibernate.hbm2ddl.auto": none

Does it mean that new default for hibernate.hbm2ddl.auto is none now?

@wilkinsona
Copy link
Member

It says Unrecognized value for "hibernate.hbm2ddl.auto": none in both logs so I don't think it's related to the problem

@mihkels
Copy link
Author

mihkels commented May 30, 2014

Sorry I copied incorrectly from clipboard updated comment.

@snicoll
Copy link
Member

snicoll commented May 31, 2014

The create-drop configuration is actually set when the application starts (check HibernateAutoConfiguration#getVendorCallback()). This is new and was introduced in a5543f1 (#894)

The problem seems to be that DataSourceAutoConfiguration runs the SQL script as a @PostContstruct callback and the database has not been created yet. If that's confirmed, we're missing a test case here and we need to understand why the sample works

@mihkels can you post your sample app somewhere? Or at least check how it differs with spring-boot-sample-data-jpa?

@dsyer, thoughts?

@dsyer
Copy link
Member

dsyer commented May 31, 2014

The hbm2ddl.auto message is a warning only, so I think it's irrelevant (there is some evidence on the internet of other people using it as an undocumented safe way to switch off the ddl features). Also as Andy pointed out it's there in both logs.

The ordering of the initialization a changed in 1.1 to accommodate liquibase running before hibernate. The same argument applies to the native Boot initialization via schema.sql (and data.sql). So I guess the problem here is that you are relying on the hibernate initialization happening before the SQL scripts are executed. That's probably not a good idea anyway because you won't want them to run at all in production, but we can have a look at your use case and see if we can make it work more naturally. I am surprised the JPA sample isn't exactly the same though.

If you look at JpaProperties you will see there is a flag to switch of the deferred hibernate initialization. That would probably get you back to where you were with 1.0 at least.

@dsyer
Copy link
Member

dsyer commented Jun 1, 2014

The difference with the Boot JPA sample is that it uses "import.sql" (Hibernate feature) not "data.sql" (Spring Boot feature).

@dsyer dsyer changed the title Unrecognized value for "hibernate.hbm2ddl.auto": none Spring Boot DataSource initialization happens too early with JPA (before hibernate schema generation) Jun 1, 2014
@mihkels mihkels changed the title Spring Boot DataSource initialization happens too early with JPA (before hibernate schema generation) Unrecognized value for "hibernate.hbm2ddl.auto": none Jun 1, 2014
@bep
Copy link
Contributor

bep commented Jun 1, 2014

This warning isn't present in boot 1 ... My guess a new version of Hibernate introduced with that prop value removed.

@philwebb
Copy link
Member

philwebb commented Jun 1, 2014

Looks like we are adding "none" here:

https://github.com/spring-projects/spring-boot/blob/master/spring-boot-autoconfigure/src/main/java/org/springframework/boot/autoconfigure/orm/jpa/JpaProperties.java#L161

Perhaps we should just omit hibernate.hbm2ddl.auto if we don't want schema generation?

@dsyer
Copy link
Member

dsyer commented Jun 1, 2014

It's just a warning. Can we ignore it and focus on the real issue here?

@philwebb
Copy link
Member

philwebb commented Jun 1, 2014

Raised #1012 for the warning issue.

Is this one a blocker for RC1?

@dsyer
Copy link
Member

dsyer commented Jun 1, 2014

I don't think it's a blocker: you can just use "import.sql" if you're using JPA.

@dsyer dsyer changed the title Unrecognized value for "hibernate.hbm2ddl.auto": none SQL initialization with "data.sql" comes too late if using hibernate DDL auto as well Jun 1, 2014
@philwebb philwebb modified the milestones: 1.1.0, 1.1.0.RC1 Jun 1, 2014
@snicoll
Copy link
Member

snicoll commented Jun 2, 2014

I wouldn't qualify it as a blocker but it's a serious regression. The spring boot feature (data.sql) is broken unless you use the deferDdl flag (I haven't tried that so I don't know if that would work).

@dsyer dsyer closed this as completed in 49a09c8 Jun 2, 2014
mdeinum pushed a commit to mdeinum/spring-boot that referenced this issue Jun 6, 2014
Added 2 new spring.datasource.* properties ("data" like
"schema", and "deferDdl" like the "spring.jpa.hibernate.*"
flag). The SQL scripts are then run separately and the "data"
ones are triggered by a new DataSourceInitializedEvent,
which is also published by the Hibernate DDL schema export.

Fixes spring-projectsgh-1006
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type: bug A general bug
Projects
None yet
Development

No branches or pull requests

6 participants