Hibernate hangs at schema export

My unit test uses in-memory HSQLDB with on-the-fly generated schema by Hibernate. Now at a particular case (not detailed for now, related to a @ManyToMany relation), the schema export hangs. When that particular relation is not used by the test case, it doesn't hang.

Logging when hangs:

[19:42:46,274][org.hibernate.tool.hbm2ddl.SchemaExport:234] - Running hbm2ddl schema export
[19:42:46,275][org.hibernate.tool.hbm2ddl.SchemaExport:252] - import file not found: /import.sql
[19:42:46,275][org.hibernate.tool.hbm2ddl.SchemaExport:262] - exporting generated schema to database
[19:42:46,275][org.hibernate.tool.hbm2ddl.SchemaExport:415] - alter table BookInfo_Author drop constraint FK5D7A0F93DD74BAC2
(hangs...)

Logging when ok:

[19:42:46,180][ INFO][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:234] - Running hbm2ddl schema export
[19:42:46,180][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:252] - import file not found: /import.sql
[19:42:46,181][ INFO][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:262] - exporting generated schema to database
[19:42:46,181][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - alter table BookInfo_Author drop constraint FK5D7A0F93DD74BAC2
[19:42:46,181][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - alter table BookInfo_Author drop constraint FK5D7A0F939758B6FA
[19:42:46,182][DEBUG][thread-main][org.hibernate开发者_开发问答.tool.hbm2ddl.SchemaExport:415] - alter table Borrow drop constraint FK76F1961594DDAB26
[19:42:46,182][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - alter table Borrow drop constraint FK76F19615BDB8772E
[19:42:46,183][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - alter table LibraryBook drop constraint FK3F0AA62433F5B726
[19:42:46,183][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - drop table Author if exists
[19:42:46,184][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - drop table BookInfo if exists
[19:42:46,184][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - drop table BookInfo_Author if exists
[19:42:46,184][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - drop table Borrow if exists
[19:42:46,184][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - drop table LibraryBook if exists
[19:42:46,185][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - drop table Member if exists
[19:42:46,185][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - create table Author (id bigint generated by default as identity (start with 1), name varchar(128) not null, primary key (id))
[19:42:46,185][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - create table BookInfo (id bigint generated by default as identity (start with 1), bookIsbn varchar(64) not null, title varchar(255) not null, primary key (id))
[19:42:46,186][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - create table BookInfo_Author (bookInfo bigint not null, author bigint not null, primary key (bookInfo, author))
[19:42:46,186][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - create table Borrow (id bigint generated by default as identity (start with 1), endDate timestamp not null, startDate timestamp not null, libraryBook_id bigint not null, member_id bigint not null, primary key (id), unique (libraryBook_id))
[19:42:46,187][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - create table LibraryBook (id bigint generated by default as identity (start with 1), bookInfo_id bigint not null, primary key (id))
[19:42:46,187][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - create table Member (id bigint generated by default as identity (start with 1), email varchar(255) not null, name varchar(255) not null, primary key (id), unique (email))
[19:42:46,188][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - alter table BookInfo_Author add constraint FK5D7A0F93DD74BAC2 foreign key (author) references Author
[19:42:46,188][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - alter table BookInfo_Author add constraint FK5D7A0F939758B6FA foreign key (bookInfo) references BookInfo
[19:42:46,189][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - alter table Borrow add constraint FK76F1961594DDAB26 foreign key (member_id) references Member
[19:42:46,189][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - alter table Borrow add constraint FK76F19615BDB8772E foreign key (libraryBook_id) references LibraryBook
[19:42:46,190][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - alter table LibraryBook add constraint FK3F0AA62433F5B726 foreign key (bookInfo_id) references BookInfo
[19:42:46,190][ INFO][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:281] - schema export complete

Particular piece of mapping on BookInfo (in Scala, but may read as Java):

  @S.ManyToMany(
    fetch = FetchType.LAZY,
    cascade = Array(CascadeType.PERSIST)
  )
  @S.JoinTable(
    name = "BookInfo_Author",
    joinColumns = Array(new S.JoinColumn(name = "bookInfo")),
    inverseJoinColumns = Array(new S.JoinColumn(name = "author"))
  )
  @BeanProperty
  var authors: java.util.Set[Author] = new java.util.HashSet[Author]()

The test case creates a BookInfo object, sets an author, and persists it using the persist method of Spring's Hibernate template. Finally, on closing the session, the schema export hangs.

Any idea?

Hanging in detail:

[19:42:46,229][ INFO][thread-main][org.hibernate.cfg.AnnotationBinder:532] - Binding entity from annotated class: glib.core.entity.Author
[19:42:46,229][ INFO][thread-main][org.hibernate.cfg.annotations.QueryBinder:86] - Binding Named query: Author.GetByName => from Author where name = :name
[19:42:46,229][ INFO][thread-main][org.hibernate.cfg.annotations.EntityBinder:530] - Bind entity glib.core.entity.Author on table Author
[19:42:46,230][ INFO][thread-main][org.hibernate.cfg.AnnotationBinder:532] - Binding entity from annotated class: glib.core.entity.BookInfo
[19:42:46,230][ INFO][thread-main][org.hibernate.cfg.annotations.EntityBinder:530] - Bind entity glib.core.entity.BookInfo on table BookInfo
[19:42:46,232][ INFO][thread-main][org.hibernate.cfg.AnnotationBinder:532] - Binding entity from annotated class: glib.core.entity.LibraryBook
[19:42:46,232][ INFO][thread-main][org.hibernate.cfg.annotations.QueryBinder:86] - Binding Named query: LibraryBook.ListByName => from LibraryBook lbook join lbook.bookInfo as info order by info.title 
[19:42:46,233][ INFO][thread-main][org.hibernate.cfg.annotations.EntityBinder:530] - Bind entity glib.core.entity.LibraryBook on table LibraryBook
[19:42:46,233][ INFO][thread-main][org.hibernate.cfg.AnnotationBinder:532] - Binding entity from annotated class: glib.core.entity.Borrow
[19:42:46,234][ INFO][thread-main][org.hibernate.cfg.annotations.EntityBinder:530] - Bind entity glib.core.entity.Borrow on table Borrow
[19:42:46,235][ INFO][thread-main][org.hibernate.cfg.AnnotationBinder:532] - Binding entity from annotated class: glib.core.entity.Member
[19:42:46,235][ INFO][thread-main][org.hibernate.cfg.annotations.QueryBinder:86] - Binding Named query: Member.GetByEmail => from Member where email = :email
[19:42:46,235][ INFO][thread-main][org.hibernate.cfg.annotations.EntityBinder:530] - Bind entity glib.core.entity.Member on table Member
[19:42:46,237][ INFO][thread-main][org.hibernate.cfg.annotations.CollectionBinder:762] - Mapping collection: glib.core.entity.BookInfo.libraryBooks -> LibraryBook
[19:42:46,237][ INFO][thread-main][org.hibernate.cfg.annotations.CollectionBinder:762] - Mapping collection: glib.core.entity.Member.borrows -> Borrow
[19:42:46,238][ INFO][thread-main][org.hibernate.cfg.Configuration:1649] - Hibernate Validator not found: ignoring
[19:42:46,238][ INFO][thread-main][org.hibernate.validator.engine.resolver.DefaultTraversableResolver:81] - Instantiated an instance of org.hibernate.validator.engine.resolver.JPATraversableResolver.
[19:42:46,241][ INFO][thread-main][org.hibernate.validator.engine.resolver.DefaultTraversableResolver:81] - Instantiated an instance of org.hibernate.validator.engine.resolver.JPATraversableResolver.
[19:42:46,243][ INFO][thread-main][org.hibernate.cfg.search.HibernateSearchEventListenerRegister:75] - Unable to find org.hibernate.search.event.FullTextIndexEventListener on the classpath. Hibernate Search is not enabled.
[19:42:46,245][ INFO][thread-main][org.hibernate.connection.DriverManagerConnectionProvider:64] - Using Hibernate built-in connection pool (not for production use!)
[19:42:46,245][ INFO][thread-main][org.hibernate.connection.DriverManagerConnectionProvider:65] - Hibernate connection pool size: 20
[19:42:46,246][ INFO][thread-main][org.hibernate.connection.DriverManagerConnectionProvider:68] - autocommit mode: false
[19:42:46,246][ INFO][thread-main][org.hibernate.connection.DriverManagerConnectionProvider:103] - using driver: org.hsqldb.jdbcDriver at URL: jdbc:hsqldb:mem:HibernateDaoTest
[19:42:46,246][ INFO][thread-main][org.hibernate.connection.DriverManagerConnectionProvider:109] - connection properties: {user=sa}
[19:42:46,247][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:117] - Database ->
       name : HSQL Database Engine
    version : 2.0.0
      major : 2
      minor : 0
[19:42:46,247][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:123] - Driver ->
       name : HSQL Database Engine Driver
    version : 2.0.0
      major : 2
      minor : 0
[19:42:46,247][ INFO][thread-main][org.hibernate.dialect.Dialect:135] - Using dialect: org.hibernate.dialect.HSQLDialect
[19:42:46,247][ INFO][thread-main][org.hibernate.transaction.TransactionFactoryFactory:59] - Using default transaction strategy (direct JDBC transactions)
[19:42:46,248][ INFO][thread-main][org.hibernate.transaction.TransactionManagerLookupFactory:80] - No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
[19:42:46,248][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:179] - Automatic flush during beforeCompletion(): disabled
[19:42:46,248][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:183] - Automatic session close at end of transaction: disabled
[19:42:46,248][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:190] - JDBC batch size: 15
[19:42:46,248][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:193] - JDBC batch updates for versioned data: disabled
[19:42:46,248][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:198] - Scrollable result sets: enabled
[19:42:46,249][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:206] - JDBC3 getGeneratedKeys(): enabled
[19:42:46,249][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:214] - Connection release mode: auto
[19:42:46,249][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:241] - Default batch fetch size: 1
[19:42:46,249][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:245] - Generate SQL with comments: disabled
[19:42:46,249][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:249] - Order SQL updates by primary key: disabled
[19:42:46,249][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:253] - Order SQL inserts for batching: disabled
[19:42:46,250][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:431] - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
[19:42:46,250][ INFO][thread-main][org.hibernate.hql.ast.ASTQueryTranslatorFactory:47] - Using ASTQueryTranslatorFactory
[19:42:46,250][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:261] - Query language substitutions: {}
[19:42:46,250][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:266] - JPA-QL strict compliance: disabled
[19:42:46,250][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:271] - Second-level cache: enabled
[19:42:46,250][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:275] - Query cache: disabled
[19:42:46,251][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:406] - Cache region factory : org.hibernate.cache.impl.NoCachingRegionFactory
[19:42:46,251][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:285] - Optimize cache for minimal puts: disabled
[19:42:46,251][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:294] - Structured second-level cache entries: disabled
[19:42:46,251][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:314] - Echoing all SQL to stdout
[19:42:46,251][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:323] - Statistics: disabled
[19:42:46,251][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:327] - Deleted entity synthetic identifier rollback: disabled
[19:42:46,252][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:343] - Default entity-mode: pojo
[19:42:46,252][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:347] - Named query checking : enabled
[19:42:46,252][ INFO][thread-main][org.hibernate.cfg.SettingsFactory:351] - Check Nullability in Core (should be disabled when Bean Validation is on): disabled
[19:42:46,254][ INFO][thread-main][org.hibernate.impl.SessionFactoryImpl:202] - building session factory
[19:42:46,255][ INFO][thread-main][org.hibernate.type.BasicTypeRegistry:150] - Type registration [wrapper_materialized_blob] overrides previous : org.hibernate.type.WrappedMaterializedBlobType@14eaec9
[19:42:46,255][ INFO][thread-main][org.hibernate.type.BasicTypeRegistry:150] - Type registration [materialized_clob] overrides previous : org.hibernate.type.MaterializedClobType@b533b8
[19:42:46,255][ INFO][thread-main][org.hibernate.type.BasicTypeRegistry:150] - Type registration [characters_clob] overrides previous : org.hibernate.type.PrimitiveCharacterArrayClobType@569c60
[19:42:46,255][ INFO][thread-main][org.hibernate.type.BasicTypeRegistry:150] - Type registration [wrapper_characters_clob] overrides previous : org.hibernate.type.CharacterArrayClobType@3468f4
[19:42:46,255][ INFO][thread-main][org.hibernate.type.BasicTypeRegistry:150] - Type registration [blob] overrides previous : org.hibernate.type.BlobType@d67067
[19:42:46,256][ INFO][thread-main][org.hibernate.type.BasicTypeRegistry:150] - Type registration [java.sql.Blob] overrides previous : org.hibernate.type.BlobType@d67067
[19:42:46,256][ INFO][thread-main][org.hibernate.type.BasicTypeRegistry:150] - Type registration [materialized_blob] overrides previous : org.hibernate.type.MaterializedBlobType@6db724
[19:42:46,256][ INFO][thread-main][org.hibernate.type.BasicTypeRegistry:150] - Type registration [clob] overrides previous : org.hibernate.type.ClobType@112da40
[19:42:46,256][ INFO][thread-main][org.hibernate.type.BasicTypeRegistry:150] - Type registration [java.sql.Clob] overrides previous : org.hibernate.type.ClobType@112da40
[19:42:46,268][ INFO][thread-main][org.hibernate.impl.SessionFactoryObjectFactory:105] - Not binding factory to JNDI, no JNDI name configured
[19:42:46,269][ INFO][thread-main][org.hibernate.validator.engine.resolver.DefaultTraversableResolver:81] - Instantiated an instance of org.hibernate.validator.engine.resolver.JPATraversableResolver.
[19:42:46,272][ INFO][thread-main][org.hibernate.validator.engine.resolver.DefaultTraversableResolver:81] - Instantiated an instance of org.hibernate.validator.engine.resolver.JPATraversableResolver.
[19:42:46,274][ INFO][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:234] - Running hbm2ddl schema export
[19:42:46,275][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:252] - import file not found: /import.sql
[19:42:46,275][ INFO][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:262] - exporting generated schema to database
[19:42:46,275][DEBUG][thread-main][org.hibernate.tool.hbm2ddl.SchemaExport:415] - alter table BookInfo_Author drop constraint FK5D7A0F93DD74BAC2

Please use HSQLDB 2.1 together with Hibernate 3.6 or later to avoid known compatibility problems. I don't know if this fixes the problem though.

The reason for me was that I had not rolled back a failed transaction (upon exception), which probably left some of the tables in locked state. Ensuring a rollback solved the problem for me.

PS: I was using MySQL database

Got the same problem using the hibernate3-maven-plugin. The following dependency config. helped:

            <plugin>
            <groupId>org.codehaus.mojo</groupId>
            <artifactId>hibernate3-maven-plugin</artifactId>
            <version>2.2</version>
            <executions>
                <execution>
                    <phase>test</phase>
                    <goals>
                        <goal>hbm2ddl</goal>
                    </goals>
                </execution>
            </executions>
            <configuration>
                <components>
                    <component>
                        <name>hbm2ddl</name>
                        <implementation>jpaconfiguration</implementation>
                    </component>
                </components>
                <componentProperties>
                    <persistenceunit>ReconciliationTestPersistence</persistenceunit>
                    <outputfilename>schema.ddl</outputfilename>
                    <drop>false</drop>
                    <create>true</create>
                    <export>false</export>
                    <format>true</format>
                    <haltonerror>false</haltonerror>
                </componentProperties>
            </configuration>
            <dependencies>
                <dependency>
                    <groupId>org.hibernate</groupId>
                    <artifactId>hibernate-tools</artifactId>
                    <version>3.2.4.GA</version>
                </dependency>
                <dependency>
                    <groupId>org.hibernate</groupId>
                    <artifactId>hibernate-entitymanager</artifactId>
                    <version>3.2.1.ga</version>
                </dependency>
                <dependency>
                    <groupId>org.hsqldb</groupId>
                    <artifactId>hsqldb</artifactId>
                    <version>2.2.4</version>
                </dependency>
            </dependencies>
        </plugin>

For me it was also hanging after printing following line during unit test run:

[INFO|org.hibernate.tool.hbm2ddl.SchemaExport|JCLLoggerAdapter] exporting generated schema to database

I was having multiple test classes. So in each of the test classes I was creating a new SessionFactory object in @BeforeClass static method as shown below using AnnotationConfiguration.

public class MyClassTest{    
    private static SessionFactory testSessionFactory = null;

    @BeforeClass    
    public static void initialize() {
        Properties testHibernateProperties = new Properties();
        // set testHibernateProperties
        AnnotationConfiguration configuration = new AnnotationConfiguration().addProperties(testHibernateProperties)
                        .addAnnotatedClass(someAnnotatedClass.class);
        testSessionFactory = configuration.buildSessionFactory();
    }

    // Adding this in each test class creating SessionFactory solved the problem
    @AfterClass
    public static void destroy(){
        testSessionFactory.close();
    }
}

I was not closing sessionFactory explicitly in any test class. For me it solved the problem when I started closing sessionFactory explicitly as shown in destroy method.