Hibernate unable to find entity in the database after adding second level cache

StackOverflow https://stackoverflow.com/questions/21417860

Question

After adding level 2 cache hibernate is returning null for an entity. Hibernate returns null for the entity (TrackingItem) because it can't find a ManyToOne relationship (Navigation) in the cache. When it attempts to query the database for the Navigation the query returns 0 rows even though it exists in the database. Without level 2 cache hibernate is able to find the entity in the database.

Here's my environment:
Server: JBoss EAP 6.1
Hibernate 4.2.0.Final
Infinispan: 5.2.6.Final

I read and re-read the infinspan guide for setting up level 2 cache here as well as the hibernate documentation on level 2 cache here.

I'm currently using CacheConcurrencyStrategy.TRANSACTIONAL with Container Managed Transactions to keep the database and cache in sync, According to the documentation Infinispan supports the CacheConcurrencyStrategy.TRANSACTIONAL.

Below are the 2 Entities (TrackingItem and Navigation) any unrelated fields and methods have been removed from the Entities.

TrackingItem.java 

@Cacheable
@Cache(usage = CacheConcurrencyStrategy.TRANSACTIONAL)
@Entity
@Table(name = "TRACKING_ITEM")
@IdClass(IdPartitionDateCompositePk.class)
public class TrackingItem extends AbstractEntity<IdPartitionDateCompositePk> {

    @Id
    @Column(name = "TRACKING_ITEM_ID", nullable = false, updatable = false)
    @GeneratedValue(strategy = GenerationType.AUTO, generator = "TRACKING_ITEM_SEQ_GENERATOR")
    @SequenceGenerator(name = "TRACKING_ITEM_SEQ_GENERATOR", sequenceName = "TRACKING_ITEM_SEQ", allocationSize = 1)
    private Long id;
    @Id
    @Temporal(TemporalType.TIMESTAMP)
    @Column(name = "PARTITION_DT", nullable = false, updatable = false)
    private Date partitionDate = new Date();
    @JoinColumn(name = "AVG_ICL_STA_VLD_VAL_ID", referencedColumnName="CLS_VLD_VAL_ID", nullable = false, updatable = false)
    @ManyToOne(optional = false)
    private ClassificationValidValue averageInclusionStatus;
    @OneToOne
    @JoinColumns({
        @JoinColumn(name = "FILE_ID",nullable = true,updatable = true),
        @JoinColumn(name = "FILE_PARTITION_DT",nullable = true,updatable = true)
    })
    private File file;
    @ManyToOne(optional = true)
    @JoinColumn(name = "EAE_INCLUSION_STA_VLD_VAL_ID", referencedColumnName="CLS_VLD_VAL_ID", nullable = true, updatable = true)
    private ClassificationValidValue exceptionStatus;
    //The navigation is not found in the cache and is then queried by hibernate.
    @ManyToOne(optional = true)
    @JoinColumns({
        @JoinColumn(name = "NAVIGATION_ID", nullable = true, updatable = true),
        @JoinColumn(name = "NAVIGATION_PARTITION_DT",nullable = true,updatable = true)
    })
    private Navigation navigation;
    @JoinColumn(name = "SOURCE_SYSTEM_ID", nullable = false)
    @ManyToOne(optional = false      private SonarApplication sourceSystem;
}

Navigation.java

@Cacheable
@Cache(usage = CacheConcurrencyStrategy.TRANSACTIONAL)
@Entity
@Table(name = "NAVIGATION")
@IdClass(IdPartitionDateCompositePk.class)
public class Navigation extends AbstractEntity<IdPartitionDateCompositePk> {
    @Id
    @Column(name = "NAVIGATION_ID", nullable = false, updatable = false)
    @GeneratedValue(strategy = GenerationType.AUTO, generator = "NAVIGATION_SEQ_GENERATOR")
    @SequenceGenerator(name = "NAVIGATION_SEQ_GENERATOR", sequenceName = "NAVIGATION_SEQ", allocationSize = 1)
    private Long id;
    @Id
    @Temporal(TemporalType.TIMESTAMP)
    @Column(name = "PARTITION_DT", nullable = false, updatable = false)
    private Date partitionDate = new Date();

    @JoinColumns({
        @JoinColumn(name = "NAVIGATION_ID"),
        @JoinColumn(name = "NAVIGATION_PARTITION_DT")
    })
    @OneToMany
    private Set<TrackingItem> trackingItems = new HashSet<TrackingItem>();

}

Standalone.xml Hibernate 2nd level cache configuration in the infinispan subsystem 

<subsystem xmlns="urn:jboss:domain:infinispan:1.4">
    <cache-container name="hibernate" default-cache="local-query" module="org.jboss.as.jpa.hibernate:4">
        <transport lock-timeout="60000"/>
        <local-cache name="local-query">
            <transaction mode="NONE"/>
            <eviction strategy="LRU" max-entries="100000"/>
            <expiration max-idle="300000"/>
        </local-cache>
        <invalidation-cache name="entity" mode="SYNC">
            <transaction mode="NON_XA"/>
            <eviction strategy="LRU" max-entries="100000"/>
            <expiration max-idle="300000"/>
        </invalidation-cache>
        <replicated-cache name="timestamps" mode="ASYNC">
            <transaction mode="NONE"/>
            <eviction strategy="NONE"/>
        </replicated-cache>
    </cache-container>
</subsystem>

Persistence.xml Properties

<properties>
    <property name="jboss.as.jpa.providerModule" value="org.hibernate"/>
    <property name="jboss.as.jpa.adapterModule" value="org.jboss.as.jpa.hibernate:4"/>
    <property name="jboss.as.jpa.adapterClass" value="org.jboss.as.jpa.hibernate4.HibernatePersistenceProviderAdaptor"/>
    <property name="hibernate.show_sql" value="false"/>
    <property name="hibernate.format_sql" value="false"/>
    <property name="hibernate.hbm2ddll.auto" value="validate"/>
    <property name="hibernate.cache.use_query_cache" value="false" />
    <property name="hibernate.cache.use_second_level_cache" value="true"/>
    <property name="hibernate.cache.generate_statistics" value="true" />
    <property name="hibernate.cache.use_structured_entries" value="false" />
    <property name="hibernate.cache.infinispan.statistics" value="false"/>
    <property name="hibernate.cache.infinispan.use_synchronization" value="true"/> 
    <property name="hibernate.cache.region.factory_class" value="org.jboss.as.jpa.hibernate4.infinispan.InfinispanRegionFactory"/>            
    <property name="hibernate.cache.infinispan.cachemanager" value="java:jboss/infinispan/hibernate" />
    <property name="hibernate.transaction.factory_class" value="org.hibernate.transaction.CMTTransactionFactory"/>
    <property name="hibernate.transaction.manager_lookup_class" value="org.hibernate.transaction.JBossTransactionManagerLookup"/>
</properties>

Lastly, here is a log entry with hibernate, infinispan and jboss.jdbc.spy set to trace to see why hibernate is returning a Null tracking item. I've bolded the most important lines and add some comments.

INFO (com.test.analyze.TrackingItemLinkNode) resolveEntity: resolving entityKey: IdPartitionDateCompositePk{id=2766422, partitionDate=2013-12-21 05:01:15.0}
INFO (com.test.analyze.TrackingItemLinkNode) resolveEntity: Checking for entity in cachedEntityMap.
INFO (com.test.analyze.TrackingItemLinkNode) resolveEntity: Entity is null. Query for it.
#Performs an entity manager find by id on the tracking item
TRACE (org.hibernate.internal.SessionImpl) Opened session at timestamp: 13906093229
DEBUG (org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl) Skipping JTA sync registration due to auto join checking
DEBUG (org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl) successfully registered Synchronization
DEBUG (org.hibernate.ejb.AbstractEntityManagerImpl) Looking for a JTA transaction to join
TRACE (org.hibernate.internal.SessionImpl) Setting flush mode to: AUTO
TRACE (org.hibernate.internal.SessionImpl) Setting cache mode to: NORMAL
TRACE (org.hibernate.event.internal.DefaultLoadEventListener) Loading entity: (com.test.db.entities.TrackingItem#component(id,partitionDate){id=2766422, partitionDate=2013-12-21 05:01:15.0})
TRACE (org.hibernate.event.internal.DefaultLoadEventListener) Attempting to resolve: (com.test.db.entities.TrackingItem#component(id,partitionDate){id=2766422, partitionDate=2013-12-21 05:01:15.0})
TRACE (org.infinispan.interceptors.InvocationContextInterceptor) Invoked with command GetKeyValueCommand {key=com.test.db.entities.TrackingItem#IdPartitionDateCompositePk{id=2766422, partitionDate=2013-12-21 05:01:15.0}, flags=null} and InvocationContext (org.infinispan.context.impl.LocalTxInvocationContext@6ec285d3)
TRACE (org.infinispan.container.EntryFactoryImpl) Exists in context? TransientCacheEntry{key=com.test.db.entities.TrackingItem#IdPartitionDateCompositePk{id=2766422, partitionDate=2013-12-21 05:01:15.0}, value=TransientCacheValue{maxIdle=300000, lastUsed=1390609322987} TransientCacheValue {value=CacheEntry(com.test.db.entities.TrackingItem)((Ljava.lang.Object;@73f59afe,N,2013-12-21 15:01:15.0,448,null,N,2013-12-21 05:02:30.0,2013-12-21 13:01:15.0,463,null,null,(Ljava.lang.Object;@192d52c,null,180,(Ljava.lang.Object;@4ee93c82,WDC,(Ljava.lang.Object;@3283a347,null,null,MDB_45374bef@eserver03,2014-01-24 16:02:36.0,null,3,2013-12-21 05:01:15.0,null,(Ljava.lang.Object;@6054a439,null,2013-12-21 13:49:14.999)}}
TRACE (org.infinispan.interceptors.CallInterceptor) Executing command: GetKeyValueCommand {key=com.test.db.entities.TrackingItem#IdPartitionDateCompositePk{id=2766422, partitionDate=2013-12-21 05:01:15.0}, flags=null}.
#The tracking item is found in the cache
TRACE (org.infinispan.commands.read.GetKeyValueCommand) Found value CacheEntry(com.test.db.entities.TrackingItem)((Ljava.lang.Object;@73f59afe,N,2013-12-21 15:01:15.0,448,null,N,2013-12-21 05:02:30.0,2013-12-21 13:01:15.0,463,null,null,(Ljava.lang.Object;@192d52c,null,180,(Ljava.lang.Object;@4ee93c82,WDC,(Ljava.lang.Object;@3283a347,null,null,MDB_45374bef@eserver03,2014-01-24 16:02:36.0,null,3,2013-12-21 05:01:15.0,null,(Ljava.lang.Object;@6054a439,null,2013-12-21 13:49:14.999)
TRACE (org.hibernate.event.internal.DefaultLoadEventListener) Converting second-level cache entry (CacheEntry(com.test.db.entities.TrackingItem)((Ljava.lang.Object;@73f59afe,N,2013-12-21 15:01:15.0,448,null,N,2013-12-21 05:02:30.0,2013-12-21 13:01:15.0,463,null,null,(Ljava.lang.Object;@192d52c,null,180,(Ljava.lang.Object;@4ee93c82,WDC,(Ljava.lang.Object;@3283a347,null,null,MDB_45374bef@eserver03,2014-01-24 16:02:36.0,null,3,2013-12-21 05:01:15.0,null,(Ljava.lang.Object;@6054a439,null,2013-12-21 13:49:14.999)) into entity : (com.test.db.entities.TrackingItem#component(id,partitionDate){id=2766422, partitionDate=2013-12-21 05:01:15.0})
#The tracking item's one to one and Many to one relationships are resolved next. All are found in the cache except for the Navigation
TRACE (org.hibernate.event.internal.DefaultLoadEventListener) Loading entity: (com.test.db.entities.ClassificationValidValue#448)
TRACE (org.hibernate.event.internal.DefaultLoadEventListener) Attempting to resolve: (com.test.db.entities.ClassificationValidValue#448)
TRACE (org.infinispan.interceptors.InvocationContextInterceptor) Invoked with command GetKeyValueCommand {key=com.test.db.entities.ClassificationValidValue#448, flags=null} and InvocationContext (org.infinispan.context.impl.LocalTxInvocationContext@79517151)
TRACE (org.infinispan.transaction.TransactionTable) Created a new local transaction: LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=null, backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@974b3
TRACE (org.infinispan.container.EntryFactoryImpl) Exists in context? null
TRACE (org.infinispan.container.EntryFactoryImpl) Retrieved from container TransientCacheEntry{key=com.test.db.entities.ClassificationValidValue#448, value=TransientCacheValue{maxIdle=300000, lastUsed=1390609323000} TransientCacheValue {value=CacheEntry(com.test.db.entities.ClassificationValidValue)(INCAVG,362,1,Y,Include In Average,INCLUDE_IN_AVERAGE,n11111,2013-06-25 09:43:11.0,INCLD_AVG)}}
TRACE (org.infinispan.interceptors.CallInterceptor) Executing command: GetKeyValueCommand {key=com.test.db.entities.ClassificationValidValue#448, flags=null}.
TRACE (org.infinispan.commands.read.GetKeyValueCommand) Found value CacheEntry(com.test.db.entities.ClassificationValidValue)(INCAVG,362,1,Y,Include In Average,INCLUDE_IN_AVERAGE,n11111,2013-06-25 09:43:11.0,INCLD_AVG)
TRACE (org.hibernate.event.internal.DefaultLoadEventListener) Converting second-level cache entry (CacheEntry(com.test.db.entities.ClassificationValidValue)(INCAVG,362,1,Y,Include In Average,INCLUDE_IN_AVERAGE,n11111,2013-06-25 09:43:11.0,INCLD_AVG)) into entity : (com.test.db.entities.ClassificationValidValue#448)
...truncated the log ...
TRACE (org.hibernate.event.internal.DefaultLoadEventListener) Loading entity: (com.test.db.entities.Navigation#component(id,partitionDate){id=391438, partitionDate=Fri Jan 24 16:15:57 PST 2014})
TRACE (org.hibernate.event.internal.DefaultLoadEventListener) Attempting to resolve: (com.test.db.entities.Navigation#component(id,partitionDate){id=391438, partitionDate=Fri Jan 24 16:15:57 PST 2014})

#Now resolve Navigation for the tracking item. The Navigation partition_dt is Jan 24 16:15:57 PST 2014 that's the timestamp it was inserted into the database. This process is running at Jan 24 16:22:03,078 PST 2014

TRACE (org.infinispan.interceptors.InvocationContextInterceptor) Invoked with command GetKeyValueCommand {key=com.test.db.entities.Navigation#IdPartitionDateCompositePk{id=391438, partitionDate=Fri Jan 24 16:15:57 PST 2014}, flags=null} and InvocationContext (org.infinispan.context.impl.LocalTxInvocationContext@334a966b)

TRACE (org.infinispan.transaction.TransactionTable) Created a new local transaction: LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=null, backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@974cf

TRACE (org.infinispan.container.EntryFactoryImpl) Exists in context? null

TRACE (org.infinispan.container.EntryFactoryImpl) Retrieved from container null

TRACE (org.infinispan.interceptors.CallInterceptor) Executing command: GetKeyValueCommand {key=com.test.db.entities.Navigation#IdPartitionDateCompositePk{id=391438, partitionDate=Fri Jan 24 16:15:57 PST 2014}, flags=null}.

TRACE (org.infinispan.commands.read.GetKeyValueCommand) Entry not found

TRACE (org.infinispan.interceptors.InvocationContextInterceptor) Invoked with command PutKeyValueCommand{key=com.test.db.entities.Navigation#IdPartitionDateCompositePk{id=391438, partitionDate=Fri Jan 24 16:15:57 PST 2014}, value=org.hibernate.cache.infinispan.access.PutFromLoadValidator$PendingPutMap@7fd40ef9, flags=null, putIfAbsent=true, lifespanMillis=-1, maxIdleTimeMillis=60000, successful=true} and InvocationContext (org.infinispan.context.SingleKeyNonTxInvocationContext@3b233eff)

TRACE (org.infinispan.util.concurrent.locks.LockManagerImpl) Attempting to lock com.test.db.entities.Navigation#IdPartitionDateCompositePk{id=391438, partitionDate=Fri Jan 24 16:15:57 PST 2014} with acquisition timeout of 10000 millis

TRACE (org.infinispan.util.concurrent.locks.containers.ReentrantPerEntryLockContainer) Creating and acquiring new lock instance for key com.test.db.entities.Navigation#IdPartitionDateCompositePk{id=391438, partitionDate=Fri Jan 24 16:15:57 PST 2014}

TRACE (org.infinispan.util.concurrent.locks.LockManagerImpl) Successfully acquired lock com.test.db.entities.Navigation#IdPartitionDateCompositePk{id=391438, partitionDate=Fri Jan 24 16:15:57 PST 2014}!

TRACE (org.infinispan.interceptors.EntryWrappingInterceptor) Wrapping entry 'com.test.db.entities.Navigation#IdPartitionDateCompositePk{id=391438, partitionDate=Fri Jan 24 16:15:57 PST 2014}'? true

TRACE (org.infinispan.container.EntryFactoryImpl) Exists in context? null

TRACE (org.infinispan.container.EntryFactoryImpl) Retrieved from container null

TRACE (org.infinispan.container.EntryFactoryImpl) Creating new entry.

TRACE (org.infinispan.interceptors.CallInterceptor) Executing command: PutKeyValueCommand{key=com.test.db.entities.Navigation#IdPartitionDateCompositePk{id=391438, partitionDate=Fri Jan 24 16:15:57 PST 2014}, value=org.hibernate.cache.infinispan.access.PutFromLoadValidator$PendingPutMap@7fd40ef9, flags=null, putIfAbsent=true, lifespanMillis=-1, maxIdleTimeMillis=60000, successful=true}.

TRACE (org.infinispan.interceptors.EntryWrappingInterceptor) About to commit entry ReadCommittedEntry(41a13c88){key=com.test.db.entities.Navigation#IdPartitionDateCompositePk{id=391438, partitionDate=Fri Jan 24 16:15:57 PST 2014}, value=org.hibernate.cache.infinispan.access.PutFromLoadValidator$PendingPutMap@7fd40ef9, oldValue=null, isCreated=true, isChanged=true, isRemoved=false, isValid=true}

TRACE (org.infinispan.container.entries.ReadCommittedEntry) Updating entry (key=com.test.db.entities.Navigation#IdPartitionDateCompositePk{id=391438, partitionDate=Fri Jan 24 16:15:57 PST 2014} removed=false valid=true changed=true created=true loaded=false value=org.hibernate.cache.infinispan.access.PutFromLoadValidator$PendingPutMap@7fd40ef9)

TRACE (org.infinispan.interceptors.EntryWrappingInterceptor) The return value is null

TRACE (org.infinispan.util.concurrent.locks.LockManagerImpl) Attempting to unlock com.test.db.entities.Navigation#IdPartitionDateCompositePk{id=391438, partitionDate=Fri Jan 24 16:15:57 PST 2014}

TRACE (org.infinispan.util.concurrent.locks.containers.ReentrantPerEntryLockContainer) Unlocking lock instance for key com.test.db.entities.Navigation#IdPartitionDateCompositePk{id=391438, partitionDate=Fri Jan 24 16:15:57 PST 2014}

#Hibernate can't find the navigation in any cache it will go to the database.

TRACE (org.hibernate.event.internal.DefaultLoadEventListener) Object not resolved in any cache: (com.test.db.entities.Navigation#component(id,partitionDate){id=391438, partitionDate=Fri Jan 24 16:15:57 PST 2014})

TRACE (org.hibernate.persister.entity.AbstractEntityPersister) Fetching entity: (com.test.db.entities.Navigation#component(id,partitionDate){id=391438, partitionDate=Fri Jan 24 16:15:57 PST 2014})

DEBUG (org.hibernate.loader.Loader) Loading entity: (com.test.db.entities.Navigation#component(id,partitionDate){id=391438, partitionDate=Fri Jan 24 16:15:57 PST 2014})

DEBUG (org.hibernate.engine.jdbc.internal.LogicalConnectionImpl) Obtaining JDBC connection

DEBUG (org.hibernate.engine.jdbc.internal.LogicalConnectionImpl) Obtained JDBC connection

DEBUG (jboss.jdbc.spy) java:/SD_DATA_SOURCE (Connection) prepareStatement(select navigation0_.NAVIGATION_ID as NAVIGATI1_12_2_, navigation0_.PARTITION_DT as PARTITIO2_12_2_, navigation0_.BLNKT_SLS_ORDER_CD as BLNKT3_12_2_, navigation0_.DEFAULT_FLG as DEFAULT4_12_2_, navigation0_.DESCRIPTION_TXT as DESCRIPT5_12_2_, navigation0_.END_DT_TM as END6_12_2_, navigation0_.EAE_INCLUSION_STA_VLD_VAL_ID as EAE13_12_2_, navigation0_.NOTE_EXIST_FLG as NOTE7_12_2_, navigation0_.REV_BY as REV8_12_2_, navigation0_.REV_DT as REV9_12_2_, navigation0_.START_DT_TM as START10_12_2_, navigation0_.TEST_FLG as TEST11_12_2_, navigation0_.TIME_BASED_FLG as TIME12_12_2_, classifica1_.CLS_VLD_VAL_ID as CLS1_2_0_, classifica1_.VALUE_ABBREVIATED_NM as VALUE2_2_0_, classifica1_.CLASSIFICATION_TYPE_ID as CLASSIF10_2_0_, classifica1_.VALUE_DISPLAY_SEQ_NBR as VALUE3_2_0_, classifica1_.DISPLAY_FLG as DISPLAY4_2_0_, classifica1_.VALUE_LONG_NM as VALUE5_2_0_, classifica1_.VALUE_MEDIUM_NM as VALUE6_2_0_, classifica1_.REV_BY as REV7_2_0_, classifica1_.REV_DT as REV8_2_0_, classifica1_.VALUE_SHORT_NM as VALUE9_2_0_, classifica2_.CLASSIFICATION_TYPE_ID as CLASSIFI1_1_1_, classifica2_.DESCRIPTION_TXT as DESCRIPT2_1_1_, classifica2_.CLASSIFICATION_TYPE_NM as CLASSIFI3_1_1_, classifica2_.REV_BY as REV4_1_1_, classifica2_.REV_DT as REV5_1_1_ from NAVIGATION navigation0_ left outer join CLASFN_VALID_VALUE classifica1_ on navigation0_.EAE_INCLUSION_STA_VLD_VAL_ID=classifica1_.CLS_VLD_VAL_ID left outer join CLASFN_TYPE classifica2_ on classifica1_.CLASSIFICATION_TYPE_ID=classifica2_.CLASSIFICATION_TYPE_ID where navigation0_.NAVIGATION_ID=? and navigation0_.PARTITION_DT=?)

TRACE (org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl) Registering statement (org.jboss.jca.adapters.jdbc.jdk6.WrappedPreparedStatementJDK6@98cee2d)

TRACE (org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl) Registering last query statement (org.jboss.jca.adapters.jdbc.jdk6.WrappedPreparedStatementJDK6@98cee2d)

TRACE (org.hibernate.type.descriptor.sql.BasicBinder) binding parameter (1) as (BIGINT) - 391438

DEBUG (jboss.jdbc.spy) java:/SD_DATA_SOURCE (PreparedStatement) setLong(1, 391438)

TRACE (org.hibernate.type.descriptor.sql.BasicBinder) binding parameter (2) as (TIMESTAMP) - Fri Jan 24 16:15:57 PST 2014

DEBUG (jboss.jdbc.spy) java:/SD_DATA_SOURCE (PreparedStatement) setTimestamp(2, 2014-01-24 16:15:57.347)

TRACE (org.hibernate.loader.Loader) Bound (3) parameters total

DEBUG (jboss.jdbc.spy) java:/SD_DATA_SOURCE (PreparedStatement) executeQuery()

TRACE (org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl) Registering result set (oracle.jdbc.driver.OracleResultSetImpl@5e781fb8)

DEBUG (jboss.jdbc.spy) java:/SD_DATA_SOURCE (ResultSet) getStatement()

DEBUG (jboss.jdbc.spy) java:/SD_DATA_SOURCE (ResultSet) getStatement()

TRACE (org.hibernate.loader.Loader) Processing result set

DEBUG (jboss.jdbc.spy) java:/SD_DATA_SOURCE (ResultSet) next()

Hibernate can't find the navigation in the database 0 rows returned 0 objects hydrated even though it exists in the database.

**TRACE (org.hibernate.loader.Loader) Done processing result set (0 rows)

TRACE (org.hibernate.loader.Loader) Total objects hydrated: 0**

TRACE (org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl) Releasing statement (org.jboss.jca.adapters.jdbc.jdk6.WrappedPreparedStatementJDK6@98cee2d)

TRACE (org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl) Closing result set (oracle.jdbc.driver.OracleResultSetImpl@5e781fb8)

DEBUG (jboss.jdbc.spy) java:/SD_DATA_SOURCE (ResultSet) close()

TRACE (org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl) Closing prepared statement (org.jboss.jca.adapters.jdbc.jdk6.WrappedPreparedStatementJDK6@98cee2d)

DEBUG (jboss.jdbc.spy) java:/SD_DATA_SOURCE (Statement) getMaxRows()

DEBUG (jboss.jdbc.spy) java:/SD_DATA_SOURCE (Statement) getQueryTimeout()

DEBUG (jboss.jdbc.spy) java:/SD_DATA_SOURCE (Statement) close()

TRACE (org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl) Starting after statement execution processing (AFTER_STATEMENT)

DEBUG (org.hibernate.engine.jdbc.internal.LogicalConnectionImpl) Releasing JDBC connection

DEBUG (jboss.jdbc.spy) java:/SD_DATA_SOURCE (Connection) isClosed()

DEBUG (jboss.jdbc.spy) java:/SD_DATA_SOURCE (Connection) getWarnings()

DEBUG (jboss.jdbc.spy) java:/SD_DATA_SOURCE (Connection) clearWarnings()

DEBUG (jboss.jdbc.spy) java:/SD_DATA_SOURCE (Connection) close()

DEBUG (org.hibernate.engine.jdbc.internal.LogicalConnectionImpl) Released JDBC connection

TRACE (org.hibernate.engine.internal.StatefulPersistenceContext) Initializing non-lazy collections

DEBUG (org.hibernate.loader.Loader) Done entity load

#Hibernate returns null for the tracking item entity because the navigation was not found

DEBUG (org.hibernate.ejb.AbstractEntityManagerImpl) HHH015013: Returning null (as required by JPA spec) rather than throwing EntityNotFoundException, as the entity (type=com.test.db.entities.TrackingItem, id=IdPartitionDateCompositePk{id=2766422, partitionDate=2013-12-21 05:01:15.0}) does not exist

TRACE (org.hibernate.internal.SessionImpl) Setting cache mode to: NORMAL

INFO (com.test.db.services.AbstractJPAPersistenceService) findById: object is: null

INFO (com.test.analyze.TrackingItemLinkNode) resolveEntity: Entity is: null

ERROR (org.jboss.as.ejb3.invocation) JBAS014134: EJB Invocation failed on component AssociationAnalyzerImpl for method public abstract com.test.analyze.QueryResult com.test.analyze.AssociationAnalyzer.getAssociations(java.lang.Object,com.test.analyze.AssociationAnalyzer$RequestType) throws com.test.analyze.AnalysisException: javax.ejb.EJBException: java.lang.NullPointerException

ERROR (org.jboss.as.ejb3.invocation) JBAS014134: EJB Invocation failed on component NavigationBlockProcessor for method public java.util.concurrent.Future com.test.processor.NavigationBlockProcessor.process(java.util.List,int,java.util.concurrent.CountDownLatch): javax.ejb.EJBException: java.lang.NullPointerException

Was it helpful?

Solution

The issue was a miss match between the Entity's partitionDate and Database column type. The Navigation's partitionDate is a Date object annotated with TemporalType.TIMESTAMP, which includes milliseconds. The Oracle column is of type DATE which does not include milliseconds. Hibernate would correctly perform a setTimestamp on the date which included milliseconds when querying the database for the navigation, but the database only stored up to the second when an insert was performed. The reason why the issue was only visible after Level 2 cache was added is the cache would store the object with the milliseconds and therefore attempt to look it up with milliseconds appended on the end. The easiest fix is to change the partition_dt to a Timestamp column and retain the milliseconds in the database.

Licensed under: CC-BY-SA with attribution
Not affiliated with StackOverflow
scroll top