Hibernate EntityManager Factory - EHCache

Question

Hi all,

I am having more problems with getting the entity manager factory up and running. Unfortunately, the error message is very vague. I'm not quite sure why it's not more descriptive, but it is what it is:

Hibernate Startup log messages (trace level), no entities configured for brevity (same error message either way except all the startup messages creating this relationship or that ...):

2010-02-12 20:48:52,501 INFO  - main - org.hibernate.cfg.annotations.Version <clinit> - Hibernate Annotations 3.4.0.GA
2010-02-12 20:48:52,510 INFO  - main - org.hibernate.cfg.Environment <clinit> - Hibernate 3.3.0.SP1
2010-02-12 20:48:52,513 INFO  - main - org.hibernate.cfg.Environment <clinit> - hibernate.properties not found
2010-02-12 20:48:52,516 INFO  - main - org.hibernate.cfg.Environment buildBytecodeProvider - Bytecode provider name : javassist
2010-02-12 20:48:52,520 INFO  - main - org.hibernate.cfg.Environment <clinit> - using JDK 1.4 java.sql.Timestamp handling
2010-02-12 20:48:52,563 INFO  - main - org.hibernate.annotations.common.Version <clinit> - Hibernate Commons Annotations 3.1.0.GA
2010-02-12 20:48:52,567 INFO  - main - org.hibernate.ejb.Version <clinit> - Hibernate EntityManager 3.4.0.GA
2010-02-12 20:48:52,582 DEBUG - main - org.hibernate.ejb.Ejb3Configuration configure - Look up for persistence unit: development
2010-02-12 20:48:52,583 TRACE - main - org.hibernate.ejb.Ejb3Configuration configure - Analysing persistence.xml: file:/mnt/projects/workspaces/development/trunk/web/WalterJWhite.com/WalterJWhite-web/target/work/webapp/WEB-INF/classes/META-INF/persistence.xml
2010-02-12 20:48:52,617 DEBUG - main - org.hibernate.util.DTDEntityResolver resolveEntity - trying to resolve system-id [http://java.sun.com/xml/ns/persistence/persistence_1_0.xsd]
2010-02-12 20:48:52,617 DEBUG - main - org.hibernate.cfg.EJB3DTDEntityResolver resolveEntity - recognized EJB3 ORM namespace; attempting to resolve on classpath under org/hibernate/ejb
2010-02-12 20:48:52,618 DEBUG - main - org.hibernate.cfg.EJB3DTDEntityResolver resolveEntity - located [http://java.sun.com/xml/ns/persistence/persistence_1_0.xsd] in classpath
2010-02-12 20:48:52,650 TRACE - main - org.hibernate.ejb.packaging.PersistenceXmlLoader parsePersistenceUnit - Persistent Unit name from persistence.xml: development
2010-02-12 20:48:52,654 TRACE - main - org.hibernate.ejb.Ejb3Configuration configure - PersistenceMetadata [
    name: development
    jtaDataSource: null
    nonJtaDataSource: jdbc/development
    transactionType: RESOURCE_LOCAL
    provider: org.hibernate.ejb.HibernatePersistence
    classes[
    ]
    packages[
    ]
    mappingFiles[
    ]
    jarFiles[
    ]
    hbmfiles: 0
    properties[
        hibernate.search.default.directory_provider: org.hibernate.search.store.FSDirectoryProvider
        hibernate.search.default.indexBase: /mnt/projects/workspaces/development/trunk/web/WalterJWhite.com/WalterJWhite-web/target/WalterJWhite-web-1.8.0-SNAPSHOT-development/lucene/indexes
        hibernate.jdbc.batch_versioned_data: true
        hibernate.ejb.event.post-insert: org.hibernate.ejb.event.EJB3PostInsertEventListener,org.hibernate.envers.event.AuditEventListener
        hibernate.connection.autocommit: true
        hibernate.ejb.event.post-collection-recreate: org.hibernate.envers.event.AuditEventListener
        hibernate.show_sql: false
        hibernate.ejb.event.pre-collection-update: org.hibernate.envers.event.AuditEventListener
        format_sql: false
        hibernate.ejb.event.post-update: org.hibernate.ejb.event.EJB3PostUpdateEventListener,org.hibernate.envers.event.AuditEventListener
        hibernate.hbm2ddl.auto: create-drop
        hibernate.cache.use_query_cache: true
        hibernate.connection.release_mode: after_transaction
        hibernate.jndi.java.naming.factory.url.pkgs: org.mortbay.naming
        use_sql_comments: false
        hibernate.jndi.java.naming.factory.initial: org.mortbay.naming.InitialContextFactory
        hibernate.cache.provider_class: org.hibernate.cache.EHCacheProvider
        hibernate.ejb.event.post-delete: org.hibernate.ejb.event.EJB3PostDeleteEventListener,org.hibernate.envers.event.AuditEventListener
        hibernate.cache.provider_configuration_file_resource_path: /ehcache.xml
        hibernate.dialect: org.hibernate.dialect.MySQLInnoDBDialect
        hibernate.ejb.event.pre-collection-remove: org.hibernate.envers.event.AuditEventListener
    ]]
2010-02-12 20:48:52,655 TRACE - main - org.hibernate.ejb.packaging.JarVisitorFactory getJarURLFromURLEntry - JAR URL from URL Entry: file:/mnt/projects/workspaces/development/trunk/web/WalterJWhite.com/WalterJWhite-web/target/work/webapp/WEB-INF/classes/META-INF/persistence.xml >> file:/mnt/projects/workspaces/development/trunk/web/WalterJWhite.com/WalterJWhite-web/target/work/webapp/WEB-INF/classes/
2010-02-12 20:48:52,659 DEBUG - main - org.hibernate.ejb.packaging.AbstractJarVisitor unqualify - Searching mapped entities in jar/par: file:/mnt/projects/workspaces/development/trunk/web/WalterJWhite.com/WalterJWhite-web/target/work/webapp/WEB-INF/classes/
2010-02-12 20:48:52,663 DEBUG - main - org.hibernate.ejb.packaging.AbstractJarVisitor addElement - File Filter matched for META-INF/orm.xml
2010-02-12 20:48:52,667 DEBUG - main - org.hibernate.ejb.Ejb3Configuration getDetectedArtifacts - Detect class: true; detect hbm: true
2010-02-12 20:48:52,669 DEBUG - main - org.hibernate.ejb.Ejb3Configuration configure - Creating Factory: development
2010-02-12 20:48:52,674 DEBUG - main - org.hibernate.util.DTDEntityResolver resolveEntity - trying to resolve system-id [file:///mnt/projects/workspaces/development/trunk/web/WalterJWhite.com/WalterJWhite-web/orm_1_0.xsd]
2010-02-12 20:48:52,674 DEBUG - main - org.hibernate.cfg.EJB3DTDEntityResolver resolveEntity - recognized EJB3 ORM namespace; attempting to resolve on classpath under org/hibernate/ejb
2010-02-12 20:48:52,675 DEBUG - main - org.hibernate.cfg.EJB3DTDEntityResolver resolveEntity - located [file:///mnt/projects/workspaces/development/trunk/web/WalterJWhite.com/WalterJWhite-web/orm_1_0.xsd] in classpath
2010-02-12 20:48:52,722 DEBUG - main - org.hibernate.cfg.AnnotationConfiguration secondPassCompile - Execute first pass mapping processing
2010-02-12 20:48:52,763 DEBUG - main - org.hibernate.cfg.AnnotationConfiguration processArtifactsOfType - Process hbm files
2010-02-12 20:48:52,764 DEBUG - main - org.hibernate.cfg.AnnotationConfiguration processArtifactsOfType - Process annotated classes
2010-02-12 20:48:52,764 DEBUG - main - org.hibernate.cfg.AnnotationConfiguration processFkSecondPassInOrder - processing fk mappings (*ToOne and JoinedSubclass)
2010-02-12 20:48:52,765 DEBUG - main - org.hibernate.cfg.Configuration secondPassCompile - processing extends queue
2010-02-12 20:48:52,765 DEBUG - main - org.hibernate.cfg.Configuration secondPassCompile - processing collection mappings
2010-02-12 20:48:52,765 DEBUG - main - org.hibernate.cfg.Configuration secondPassCompile - processing native query and ResultSetMapping mappings
2010-02-12 20:48:52,765 DEBUG - main - org.hibernate.cfg.Configuration secondPassCompile - processing association property references
2010-02-12 20:48:52,766 DEBUG - main - org.hibernate.cfg.Configuration secondPassCompile - processing foreign key constraints
2010-02-12 20:48:52,779 DEBUG - main - org.hibernate.ejb.util.NamingHelper bind - No JNDI name configured for binding Ejb3Configuration
2010-02-12 20:48:52,789 DEBUG - main - org.hibernate.cfg.Configuration buildSessionFactory - Preparing to build session factory with filters : {}
2010-02-12 20:48:52,790 DEBUG - main - org.hibernate.cfg.AnnotationConfiguration secondPassCompile - Execute first pass mapping processing
2010-02-12 20:48:52,790 DEBUG - main - org.hibernate.cfg.AnnotationConfiguration processArtifactsOfType - Process hbm files
2010-02-12 20:48:52,790 DEBUG - main - org.hibernate.cfg.AnnotationConfiguration processArtifactsOfType - Process annotated classes
2010-02-12 20:48:52,790 DEBUG - main - org.hibernate.cfg.AnnotationConfiguration processFkSecondPassInOrder - processing fk mappings (*ToOne and JoinedSubclass)
2010-02-12 20:48:52,791 DEBUG - main - org.hibernate.cfg.Configuration secondPassCompile - processing extends queue
2010-02-12 20:48:52,791 DEBUG - main - org.hibernate.cfg.Configuration secondPassCompile - processing collection mappings
2010-02-12 20:48:52,791 DEBUG - main - org.hibernate.cfg.Configuration secondPassCompile - processing native query and ResultSetMapping mappings
2010-02-12 20:48:52,792 DEBUG - main - org.hibernate.cfg.Configuration secondPassCompile - processing association property references
2010-02-12 20:48:52,792 DEBUG - main - org.hibernate.cfg.Configuration secondPassCompile - processing foreign key constraints
2010-02-12 20:48:52,797 INFO  - main - org.hibernate.util.NamingHelper getInitialContext - JNDI InitialContext properties:{java.naming.factory.initial=org.mortbay.naming.InitialContextFactory, java.naming.factory.url.pkgs=org.mortbay.naming}
2010-02-12 20:48:52,804 INFO  - main - org.hibernate.connection.DatasourceConnectionProvider configure - Using datasource: jdbc/development
2010-02-12 20:48:53,230 INFO  - main - org.hibernate.cfg.SettingsFactory buildSettings - RDBMS: MySQL, version: 5.1.37-1ubuntu5.1
2010-02-12 20:48:53,231 INFO  - main - org.hibernate.cfg.SettingsFactory buildSettings - JDBC driver: MySQL-AB JDBC Driver, version: mysql-connector-java-5.1.6 ( Revision: ${svn.Revision} )
2010-02-12 20:48:53,244 INFO  - main - org.hibernate.dialect.Dialect <init> - Using dialect: org.hibernate.dialect.MySQLInnoDBDialect
2010-02-12 20:48:53,271 INFO  - main - org.hibernate.transaction.TransactionFactoryFactory buildTransactionFactory - Transaction strategy: org.hibernate.transaction.JDBCTransactionFactory
2010-02-12 20:48:53,273 INFO  - main - org.hibernate.transaction.TransactionManagerLookupFactory getTransactionManagerLookup - No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
2010-02-12 20:48:53,273 INFO  - main - org.hibernate.cfg.SettingsFactory buildSettings - Automatic flush during beforeCompletion(): disabled
2010-02-12 20:48:53,273 INFO  - main - org.hibernate.cfg.SettingsFactory buildSettings - Automatic session close at end of transaction: disabled
2010-02-12 20:48:53,274 INFO  - main - org.hibernate.cfg.SettingsFactory buildSettings - JDBC batch size: 15
2010-02-12 20:48:53,274 INFO  - main - org.hibernate.cfg.SettingsFactory buildSettings - JDBC batch updates for versioned data: enabled
2010-02-12 20:48:53,275 INFO  - main - org.hibernate.cfg.SettingsFactory buildSettings - Scrollable result sets: enabled
2010-02-12 20:48:53,275 DEBUG - main - org.hibernate.cfg.SettingsFactory buildSettings - Wrap result sets: disabled
2010-02-12 20:48:53,275 INFO  - main - org.hibernate.cfg.SettingsFactory buildSettings - JDBC3 getGeneratedKeys(): enabled
2010-02-12 20:48:53,275 INFO  - main - org.hibernate.cfg.SettingsFactory buildSettings - Connection release mode: after_transaction
2010-02-12 20:48:53,276 INFO  - main - org.hibernate.cfg.SettingsFactory buildSettings - Maximum outer join fetch depth: 2
2010-02-12 20:48:53,277 INFO  - main - org.hibernate.cfg.SettingsFactory buildSettings - Default batch fetch size: 1
2010-02-12 20:48:53,277 INFO  - main - org.hibernate.cfg.SettingsFactory buildSettings - Generate SQL with comments: disabled
2010-02-12 20:48:53,277 INFO  - main - org.hibernate.cfg.SettingsFactory buildSettings - Order SQL updates by primary key: disabled
2010-02-12 20:48:53,277 INFO  - main - org.hibernate.cfg.SettingsFactory buildSettings - Order SQL inserts for batching: disabled
2010-02-12 20:48:53,278 INFO  - main - org.hibernate.cfg.SettingsFactory createQueryTranslatorFactory - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
2010-02-12 20:48:53,279 INFO  - main - org.hibernate.hql.ast.ASTQueryTranslatorFactory <init> - Using ASTQueryTranslatorFactory
2010-02-12 20:48:53,280 INFO  - main - org.hibernate.cfg.SettingsFactory buildSettings - Query language substitutions: {}
2010-02-12 20:48:53,280 INFO  - main - org.hibernate.cfg.SettingsFactory buildSettings - JPA-QL strict compliance: enabled
2010-02-12 20:48:53,280 INFO  - main - org.hibernate.cfg.SettingsFactory buildSettings - Second-level cache: enabled
2010-02-12 20:48:53,282 INFO  - main - org.hibernate.cfg.SettingsFactory buildSettings - Query cache: enabled
2010-02-12 20:48:53,285 INFO  - main - org.hibernate.cfg.SettingsFactory createRegionFactory - Cache region factory : org.hibernate.cache.impl.bridge.RegionFactoryCacheProviderBridge
2010-02-12 20:48:53,285 INFO  - main - org.hibernate.cache.impl.bridge.RegionFactoryCacheProviderBridge <init> - Cache provider: org.hibernate.cache.EHCacheProvider

It always dies at EHCacheProvider. The issues I had in the past were from me splitting my projects out into 50 sub-projects (30 model projects, listener projects, filter projects, ui projects, web action projects, etc.). It is still quite possible that one of my projects is not using the latest version (although unlikely) causing this type of error.

This is my log4j configuration. I am trying to separate stuff in the logs so I can more easily discern where a problem is coming from and just look at what I need to to solve a problem.

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<!--
   | For more configuration infromation and examples see the Jakarta Log4j
   | owebsite: http://jakarta.apache.org/log4j
 -->
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="false">
    <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
        <param name="Target" value="System.out"/>

        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="${logging.pattern}"/>
        </layout>
    </appender>
    <appender name="HIBERNATE_FILE" class="org.apache.log4j.FileAppender">
        <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
        <param name="File" value="${log.directory}hibernate.log"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="${logging.pattern}"/>
        </layout>
    </appender>
    <appender name="C3P0_FILE" class="org.apache.log4j.FileAppender">
        <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
        <param name="File" value="${log.directory}c3p0.log"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="${logging.pattern}"/>
        </layout>
    </appender>
    <appender name="SEAM_FILE" class="org.apache.log4j.FileAppender">
        <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
        <param name="File" value="${log.directory}seam.log"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="${logging.pattern}"/>
        </layout>
    </appender>
    <appender name="FILE" class="org.apache.log4j.FileAppender">
        <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
        <param name="File" value="${log.directory}${pom.artifactId}.log"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="${logging.pattern}"/>
        </layout>
    </appender>
    <appender name="DATABASE_DEPLOYMENT_FILE" class="org.apache.log4j.FileAppender">
        <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
        <param name="File" value="${log.directory}${pom.artifactId}.database.deployment.log"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="${logging.pattern}"/>
        </layout>
    </appender>

    <logger name="org">
        <level value="${components.logLevel}"/>
    </logger>
    <logger name="net">
        <level value="${components.logLevel}"/>
    </logger>
    <logger name="com">
        <level value="${components.logLevel}"/>
    </logger>

    <logger name="javax">
        <level value="${components.logLevel}"/>
    </logger>

    <logger name="org.jboss.seam" additivity="false">
        <level value="${seam.logLevel}"/>
        <appender-ref ref="SEAM_FILE"/>
    </logger>
    <!--    Only put hibernate stuff in the hibernate file, be sure to not include it in the application logs   -->
    <logger name="org.hibernate" additivity="false">
        <level value="TRACE"/>
        <appender-ref ref="HIBERNATE_FILE"/>
    </logger>
    <logger name="com.mchange" additivity="false">
        <level value="${components.logLevel}" />
        <appender-ref ref="C3P0_FILE"/>
    </logger>

    <logger name="com.walterjwhite" additivity="false">
        <level value="${walterjwhite.logLevel}"/>
        <appender-ref ref="FILE"/>
    </logger>

    <!--    Log the database import script to a separate file to keep information clean and simple  -->
    <logger name="com.walterjwhite.service.databaseImporter" additivity="false">
        <level value="TRACE"/>
        <appender-ref ref="DATABASE_DEPLOYMENT_FILE"/>
    </logger>

    <root>
        <priority value="${components.logLevel}"/>

        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="FILE"/>
    </root>
</log4j:configuration>

Answer 1

You hibernate log does not show an error. Why do you think anything is wrong? Is there an actual error message later on?

Answer 2

I found out the problem. I had to attach a debugger to the startup process to see that the root cause was a class not found exception. The cause itself was null which is why the exception was logged the way it was.

I've mixed and matched versions here that apparently a class name changed for the cache provider I'm using which caused this whole mess.

Walter