[infinispan-issues] [JBoss JIRA] (ISPN-9432) NPE during transaction commit - Hibernate 2 level cache

[ https://issues.jboss.org/browse/ISPN-9432?page=com.atlassian.jira.plugin.... ] Diego Lovison updated ISPN-9432: -------------------------------- Description: I was considering to send a link with my repository but it is current in dev. I decided to attach the source code. It will be nice have a test case for infinispan-configs-local.xml Here is the stack trace. {noformat} Aug 15, 2018 3:04:52 PM org.hibernate.jpa.internal.util.LogHelper logPersistenceUnitInformation INFO: HHH000204: Processing PersistenceUnitInfo [ name: h2 ...] Aug 15, 2018 3:04:52 PM org.hibernate.Version logVersion INFO: HHH000412: Hibernate Core {5.3.5.Final} Aug 15, 2018 3:04:52 PM org.hibernate.cfg.Environment <clinit> INFO: HHH000206: hibernate.properties not found Aug 15, 2018 3:04:53 PM org.hibernate.annotations.common.reflection.java.JavaReflectionManager <clinit> INFO: HCANN000001: Hibernate Commons Annotations {5.0.4.Final} Aug 15, 2018 3:04:53 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure WARN: HHH10001002: Using Hibernate built-in connection pool (not for production use!) Aug 15, 2018 3:04:53 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator INFO: HHH10001005: using driver [org.h2.Driver] at URL [jdbc:h2:mem:] Aug 15, 2018 3:04:53 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator INFO: HHH10001001: Connection properties: {user=sa} Aug 15, 2018 3:04:53 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator INFO: HHH10001003: Autocommit mode: false Aug 15, 2018 3:04:53 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl$PooledConnections <init> INFO: HHH000115: Hibernate connection pool size: 20 (min=1) Aug 15, 2018 3:04:53 PM org.hibernate.dialect.Dialect <init> INFO: HHH000400: Using dialect: org.hibernate.dialect.H2Dialect Aug 15, 2018 3:04:54 PM org.infinispan.factories.GlobalComponentRegistry start INFO: ISPN000128: Infinispan version: Infinispan 'WIP' 9.4.0-SNAPSHOT Aug 15, 2018 3:04:54 PM org.infinispan.factories.GlobalComponentRegistry lambda$warnAboutUberJarDuplicates$1 WARN: ISPN000411: Classpath does not look correct. Make sure you are not mixing uber and jars Hibernate: drop table events if exists Aug 15, 2018 3:04:54 PM org.hibernate.resource.transaction.backend.jdbc.internal.DdlTransactionIsolatorNonJtaImpl getIsolatedConnection Hibernate: create table events (id bigint not null, event_date timestamp, title varchar(255), primary key (id)) INFO: HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess@f5b6e78] for (non-JTA) DDL execution was not in auto-commit mode; the Connection 'local transaction' will be committed and the Connection will be set into auto-commit mode. Aug 15, 2018 3:04:54 PM org.hibernate.resource.transaction.backend.jdbc.internal.DdlTransactionIsolatorNonJtaImpl getIsolatedConnection INFO: HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess@697a34af] for (non-JTA) DDL execution was not in auto-commit mode; the Connection 'local transaction' will be committed and the Connection will be set into auto-commit mode. Aug 15, 2018 3:04:54 PM org.hibernate.tool.schema.internal.SchemaCreatorImpl applyImportSources INFO: HHH000476: Executing import script 'org.hibernate.tool.schema.internal.exec.ScriptSourceInputNonExistentImpl@3b48e183' Hibernate: select max(id) from events Hibernate: insert into events (event_date, title, id) values (?, ?, ?) Aug 15, 2018 3:04:54 PM org.infinispan.hibernate.cache.v53.impl.Sync transactionCompleted ERROR: HHH025036: Operation #0 scheduled after transaction completion failed (transaction successful? true) java.lang.NullPointerException at org.infinispan.hibernate.cache.v53.impl.InvalidationInvocation.invoke(InvalidationInvocation.java:35) at org.infinispan.hibernate.cache.v53.impl.Sync.transactionCompleted(Sync.java:105) at org.hibernate.internal.AbstractSharedSessionContract.afterTransactionCompletion(AbstractSharedSessionContract.java:434) at org.hibernate.internal.SessionImpl.afterTransactionCompletion(SessionImpl.java:2522) at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.afterTransactionCompletion(JdbcCoordinatorImpl.java:479) at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.afterCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:198) at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$400(JdbcResourceLocalTransactionCoordinatorImpl.java:39) at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:273) at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:98) at com.github.diegolovison.example.infinispan.Hibernate2LevelCacheExample.main(Hibernate2LevelCacheExample.java:21) Aug 15, 2018 3:04:54 PM org.infinispan.hibernate.cache.v53.impl.Sync transactionCompleted ERROR: HHH025036: Operation #1 scheduled after transaction completion failed (transaction successful? true) java.lang.NullPointerException at org.infinispan.hibernate.cache.v53.impl.InvalidationInvocation.invoke(InvalidationInvocation.java:35) at org.infinispan.hibernate.cache.v53.impl.Sync.transactionCompleted(Sync.java:105) at org.hibernate.internal.AbstractSharedSessionContract.afterTransactionCompletion(AbstractSharedSessionContract.java:434) at org.hibernate.internal.SessionImpl.afterTransactionCompletion(SessionImpl.java:2522) at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.afterTransactionCompletion(JdbcCoordinatorImpl.java:479) at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.afterCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:198) at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$400(JdbcResourceLocalTransactionCoordinatorImpl.java:39) at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:273) at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:98) at com.github.diegolovison.example.infinispan.Hibernate2LevelCacheExample.main(Hibernate2LevelCacheExample.java:21) Aug 15, 2018 3:04:54 PM org.hibernate.engine.internal.StatisticalLoggingSessionEventListener end INFO: Session Metrics { 18591 nanoseconds spent acquiring 1 JDBC connections; 36269 nanoseconds spent releasing 1 JDBC connections; 1318932 nanoseconds spent preparing 3 JDBC statements; 472926 nanoseconds spent executing 3 JDBC statements; 0 nanoseconds spent executing 0 JDBC batches; 15572473 nanoseconds spent performing 4 L2C puts; 0 nanoseconds spent performing 0 L2C hits; 0 nanoseconds spent performing 0 L2C misses; 25937336 nanoseconds spent executing 1 flushes (flushing a total of 2 entities and 0 collections); 0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections) } Hibernate: insert into events (event_date, title, id) values (?, ?, ?) Aug 15, 2018 3:04:54 PM org.hibernate.tool.schema.internal.SchemaDropperImpl$DelayedDropActionImpl perform INFO: HHH000477: Starting delayed evictData of schema as part of SessionFactory shut-down' Aug 15, 2018 3:04:54 PM org.hibernate.resource.transaction.backend.jdbc.internal.DdlTransactionIsolatorNonJtaImpl getIsolatedConnection INFO: HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess@55651434] for (non-JTA) DDL execution was not in auto-commit mode; the Connection 'local transaction' will be committed and the Connection will be set into auto-commit mode. Hibernate: drop table events if exists Aug 15, 2018 3:04:54 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl stop INFO: HHH10001008: Cleaning up connection pool [jdbc:h2:mem:] Process finished with exit code 0 {noformat} was: I was considering to send a link with my repository but it is current in dev. I decided to attach the source code. +5cents. It will be nice have a test case for infinispan-configs-local.xml Here is the stack trace. {noformat} Aug 15, 2018 3:04:52 PM org.hibernate.jpa.internal.util.LogHelper logPersistenceUnitInformation INFO: HHH000204: Processing PersistenceUnitInfo [ name: h2 ...] Aug 15, 2018 3:04:52 PM org.hibernate.Version logVersion INFO: HHH000412: Hibernate Core {5.3.5.Final} Aug 15, 2018 3:04:52 PM org.hibernate.cfg.Environment <clinit> INFO: HHH000206: hibernate.properties not found Aug 15, 2018 3:04:53 PM org.hibernate.annotations.common.reflection.java.JavaReflectionManager <clinit> INFO: HCANN000001: Hibernate Commons Annotations {5.0.4.Final} Aug 15, 2018 3:04:53 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure WARN: HHH10001002: Using Hibernate built-in connection pool (not for production use!) Aug 15, 2018 3:04:53 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator INFO: HHH10001005: using driver [org.h2.Driver] at URL [jdbc:h2:mem:] Aug 15, 2018 3:04:53 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator INFO: HHH10001001: Connection properties: {user=sa} Aug 15, 2018 3:04:53 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator INFO: HHH10001003: Autocommit mode: false Aug 15, 2018 3:04:53 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl$PooledConnections <init> INFO: HHH000115: Hibernate connection pool size: 20 (min=1) Aug 15, 2018 3:04:53 PM org.hibernate.dialect.Dialect <init> INFO: HHH000400: Using dialect: org.hibernate.dialect.H2Dialect Aug 15, 2018 3:04:54 PM org.infinispan.factories.GlobalComponentRegistry start INFO: ISPN000128: Infinispan version: Infinispan 'WIP' 9.4.0-SNAPSHOT Aug 15, 2018 3:04:54 PM org.infinispan.factories.GlobalComponentRegistry lambda$warnAboutUberJarDuplicates$1 WARN: ISPN000411: Classpath does not look correct. Make sure you are not mixing uber and jars Hibernate: drop table events if exists Aug 15, 2018 3:04:54 PM org.hibernate.resource.transaction.backend.jdbc.internal.DdlTransactionIsolatorNonJtaImpl getIsolatedConnection Hibernate: create table events (id bigint not null, event_date timestamp, title varchar(255), primary key (id)) INFO: HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess@f5b6e78] for (non-JTA) DDL execution was not in auto-commit mode; the Connection 'local transaction' will be committed and the Connection will be set into auto-commit mode. Aug 15, 2018 3:04:54 PM org.hibernate.resource.transaction.backend.jdbc.internal.DdlTransactionIsolatorNonJtaImpl getIsolatedConnection INFO: HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess@697a34af] for (non-JTA) DDL execution was not in auto-commit mode; the Connection 'local transaction' will be committed and the Connection will be set into auto-commit mode. Aug 15, 2018 3:04:54 PM org.hibernate.tool.schema.internal.SchemaCreatorImpl applyImportSources INFO: HHH000476: Executing import script 'org.hibernate.tool.schema.internal.exec.ScriptSourceInputNonExistentImpl@3b48e183' Hibernate: select max(id) from events Hibernate: insert into events (event_date, title, id) values (?, ?, ?) Aug 15, 2018 3:04:54 PM org.infinispan.hibernate.cache.v53.impl.Sync transactionCompleted ERROR: HHH025036: Operation #0 scheduled after transaction completion failed (transaction successful? true) java.lang.NullPointerException at org.infinispan.hibernate.cache.v53.impl.InvalidationInvocation.invoke(InvalidationInvocation.java:35) at org.infinispan.hibernate.cache.v53.impl.Sync.transactionCompleted(Sync.java:105) at org.hibernate.internal.AbstractSharedSessionContract.afterTransactionCompletion(AbstractSharedSessionContract.java:434) at org.hibernate.internal.SessionImpl.afterTransactionCompletion(SessionImpl.java:2522) at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.afterTransactionCompletion(JdbcCoordinatorImpl.java:479) at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.afterCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:198) at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$400(JdbcResourceLocalTransactionCoordinatorImpl.java:39) at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:273) at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:98) at com.github.diegolovison.example.infinispan.Hibernate2LevelCacheExample.main(Hibernate2LevelCacheExample.java:21) Aug 15, 2018 3:04:54 PM org.infinispan.hibernate.cache.v53.impl.Sync transactionCompleted ERROR: HHH025036: Operation #1 scheduled after transaction completion failed (transaction successful? true) java.lang.NullPointerException at org.infinispan.hibernate.cache.v53.impl.InvalidationInvocation.invoke(InvalidationInvocation.java:35) at org.infinispan.hibernate.cache.v53.impl.Sync.transactionCompleted(Sync.java:105) at org.hibernate.internal.AbstractSharedSessionContract.afterTransactionCompletion(AbstractSharedSessionContract.java:434) at org.hibernate.internal.SessionImpl.afterTransactionCompletion(SessionImpl.java:2522) at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.afterTransactionCompletion(JdbcCoordinatorImpl.java:479) at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.afterCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:198) at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$400(JdbcResourceLocalTransactionCoordinatorImpl.java:39) at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:273) at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:98) at com.github.diegolovison.example.infinispan.Hibernate2LevelCacheExample.main(Hibernate2LevelCacheExample.java:21) Aug 15, 2018 3:04:54 PM org.hibernate.engine.internal.StatisticalLoggingSessionEventListener end INFO: Session Metrics { 18591 nanoseconds spent acquiring 1 JDBC connections; 36269 nanoseconds spent releasing 1 JDBC connections; 1318932 nanoseconds spent preparing 3 JDBC statements; 472926 nanoseconds spent executing 3 JDBC statements; 0 nanoseconds spent executing 0 JDBC batches; 15572473 nanoseconds spent performing 4 L2C puts; 0 nanoseconds spent performing 0 L2C hits; 0 nanoseconds spent performing 0 L2C misses; 25937336 nanoseconds spent executing 1 flushes (flushing a total of 2 entities and 0 collections); 0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections) } Hibernate: insert into events (event_date, title, id) values (?, ?, ?) Aug 15, 2018 3:04:54 PM org.hibernate.tool.schema.internal.SchemaDropperImpl$DelayedDropActionImpl perform INFO: HHH000477: Starting delayed evictData of schema as part of SessionFactory shut-down' Aug 15, 2018 3:04:54 PM org.hibernate.resource.transaction.backend.jdbc.internal.DdlTransactionIsolatorNonJtaImpl getIsolatedConnection INFO: HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess@55651434] for (non-JTA) DDL execution was not in auto-commit mode; the Connection 'local transaction' will be committed and the Connection will be set into auto-commit mode. Hibernate: drop table events if exists Aug 15, 2018 3:04:54 PM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl stop INFO: HHH10001008: Cleaning up connection pool [jdbc:h2:mem:] Process finished with exit code 0 {noformat} -- This message was sent by Atlassian JIRA (v7.5.0#75005)