[jboss-jira] [JBoss JIRA] (DROOLS-1093) Database Outage causes Session Persistence to break

[ https://issues.jboss.org/browse/DROOLS-1093?page=com.atlassian.jira.plugi... ] Artur Kronenberg commented on DROOLS-1093: ------------------------------------------ Finally I managed to reproduce it. As with the history of my reproducers, the code is a bit weird and there are manual instructions. 1. I am using a mysql database for persistence. (sadly the datasource must be a pooled datasource of the type I am using. I use the dropwizard factory to create it since this is as close to my setup as it gets and I did not manage to reproduce it any other way - using gradle should be fine to pull in that dep) 2. I create a persisted session the normal way 3. Insert an event that inserts 1k models into the session 4. create a timer task that inserts expiry facts that randomly match a model fact and retract them. (this task for some reason has to be set to at least 30 seconds (that is what i tried it with). If shorter, the effect is different ant the NPE does not appear) 5. now the fun part: 5.1. Use Starter to start the new application. (main method has to call create()) 5.2. Once you see this message in the output, stop the database (mysql.server stop) {code:java} Expiry run. Sleep for a while. Rules: XXXX Sleep {code} 5.3. After you stopped the DB, wait for 30 seconds for the first exeption: {code:java} 16:15:53.212 [pool-1-thread-1] WARN o.d.p.SingleSessionCommandService - Could not commit session java.lang.RuntimeException: Unable to commit transaction at org.drools.persistence.jta.JtaTransactionManager.commit(JtaTransactionManager.java:239) ~[drools-persistence-jpa-6.3.0.Final.jar:6.3.0.Final] at org.drools.persistence.SingleSessionCommandService$TransactionInterceptor.execute(SingleSessionCommandService.java:587) ~[drools-persistence-jpa-6.3.0.Final.jar:6.3.0.Final] at org.drools.persistence.SingleSessionCommandService.execute(SingleSessionCommandService.java:377) [drools-persistence-jpa-6.3.0.Final.jar:6.3.0.Final] at org.drools.core.command.impl.CommandBasedStatefulKnowledgeSession.insert(CommandBasedStatefulKnowledgeSession.java:410) [drools-core-6.3.0.Final.jar:6.3.0.Final] at org.pandaa.test.Starter$2.lambda$0(Starter.java:154) [bin/:na] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_74] at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_74] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[na:1.8.0_74] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[na:1.8.0_74] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_74] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_74] at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_74] Caused by: bitronix.tm.internal.BitronixRollbackException: RuntimeException thrown during beforeCompletion cycle caused transaction rollback at bitronix.tm.BitronixTransaction.commit(BitronixTransaction.java:241) ~[btm-2.1.4.jar:2.1.4] at bitronix.tm.BitronixTransactionManager.commit(BitronixTransactionManager.java:143) ~[btm-2.1.4.jar:2.1.4] at org.drools.persistence.jta.JtaTransactionManager.commit(JtaTransactionManager.java:236) ~[drools-persistence-jpa-6.3.0.Final.jar:6.3.0.Final] ... 11 common frames omitted Caused by: javax.persistence.PersistenceException: org.hibernate.exception.JDBCConnectionException: could not execute statement at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1387) ~[hibernate-entitymanager-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1310) ~[hibernate-entitymanager-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1316) ~[hibernate-entitymanager-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.ejb.AbstractEntityManagerImpl$CallbackExceptionMapperImpl.mapManagedFlushFailure(AbstractEntityManagerImpl.java:1510) ~[hibernate-entitymanager-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorNonTrackingImpl.beforeCompletion(SynchronizationCallbackCoordinatorNonTrackingImpl.java:114) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization.beforeCompletion(RegisteredSynchronization.java:53) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] at bitronix.tm.BitronixTransaction.fireBeforeCompletionEvent(BitronixTransaction.java:532) ~[btm-2.1.4.jar:2.1.4] at bitronix.tm.BitronixTransaction.commit(BitronixTransaction.java:235) ~[btm-2.1.4.jar:2.1.4] ... 13 common frames omitted Caused by: org.hibernate.exception.JDBCConnectionException: could not execute statement at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:132) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:124) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:109) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:189) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3240) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3138) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3468) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:140) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.engine.spi.ActionQueue.execute(ActionQueue.java:395) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:387) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:304) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:349) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:56) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1195) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:404) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] at org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorNonTrackingImpl.beforeCompletion(SynchronizationCallbackCoordinatorNonTrackingImpl.java:109) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] ... 16 common frames omitted Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure Last packet sent to the server was 0 ms ago. at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:1.8.0_74] at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[na:1.8.0_74] at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_74] at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_74] at com.mysql.jdbc.Util.handleNewInstance(Util.java:406) ~[mysql-connector-java-5.1.6.jar:na] at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1074) ~[mysql-connector-java-5.1.6.jar:na] at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2985) ~[mysql-connector-java-5.1.6.jar:na] at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2871) ~[mysql-connector-java-5.1.6.jar:na] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3414) ~[mysql-connector-java-5.1.6.jar:na] at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1936) ~[mysql-connector-java-5.1.6.jar:na] at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2060) ~[mysql-connector-java-5.1.6.jar:na] at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542) ~[mysql-connector-java-5.1.6.jar:na] at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734) ~[mysql-connector-java-5.1.6.jar:na] at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2019) ~[mysql-connector-java-5.1.6.jar:na] at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1937) ~[mysql-connector-java-5.1.6.jar:na] at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1922) ~[mysql-connector-java-5.1.6.jar:na] at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:186) ~[hibernate-core-4.2.21.Final.jar:4.2.21.Final] ... 28 common frames omitted Caused by: java.net.SocketException: Connection reset at java.net.SocketInputStream.read(SocketInputStream.java:209) ~[na:1.8.0_74] at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[na:1.8.0_74] at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113) ~[mysql-connector-java-5.1.6.jar:na] at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160) ~[mysql-connector-java-5.1.6.jar:na] at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188) ~[mysql-connector-java-5.1.6.jar:na] at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2428) ~[mysql-connector-java-5.1.6.jar:na] at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2882) ~[mysql-connector-java-5.1.6.jar:na] ... 38 common frames omitted {code} 5.4. Start the server again once you saw the exception. Wait for 30 seconds 5.5. Once you see the same message as in 5.2. stop the database again 5.6. Wait for the exception, then start the database again 5.7. The next time it tries to insert the ExpiryFact, it will try to re-init the session and blow up with a NullPointerException {code:java} java.lang.RuntimeException: Unable to load session snapshot at org.drools.persistence.SessionMarshallingHelper.loadSnapshot(SessionMarshallingHelper.java:103) ~[drools-persistence-jpa-6.3.0.Final.jar:6.3.0.Final] at org.drools.persistence.SingleSessionCommandService.initExistingKnowledgeSession(SingleSessionCommandService.java:242) [drools-persistence-jpa-6.3.0.Final.jar:6.3.0.Final] at org.drools.persistence.SingleSessionCommandService$TransactionInterceptor.execute(SingleSessionCommandService.java:557) ~[drools-persistence-jpa-6.3.0.Final.jar:6.3.0.Final] at org.drools.persistence.SingleSessionCommandService.execute(SingleSessionCommandService.java:377) [drools-persistence-jpa-6.3.0.Final.jar:6.3.0.Final] at org.drools.core.command.impl.CommandBasedStatefulKnowledgeSession.insert(CommandBasedStatefulKnowledgeSession.java:410) [drools-core-6.3.0.Final.jar:6.3.0.Final] at org.pandaa.test.Starter$2.lambda$0(Starter.java:154) [bin/:na] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_74] at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_74] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[na:1.8.0_74] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[na:1.8.0_74] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_74] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_74] at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_74] Caused by: java.lang.NullPointerException: null at org.drools.core.marshalling.impl.ProtobufInputMarshaller.readTruthMaintenanceSystem(ProtobufInputMarshaller.java:586) ~[drools-core-6.3.0.Final.jar:6.3.0.Final] at org.drools.core.marshalling.impl.ProtobufInputMarshaller.readSession(ProtobufInputMarshaller.java:247) ~[drools-core-6.3.0.Final.jar:6.3.0.Final] at org.drools.core.marshalling.impl.ProtobufInputMarshaller.readSession(ProtobufInputMarshaller.java:118) ~[drools-core-6.3.0.Final.jar:6.3.0.Final] at org.drools.core.marshalling.impl.ProtobufMarshaller.unmarshall(ProtobufMarshaller.java:131) ~[drools-core-6.3.0.Final.jar:6.3.0.Final] at org.drools.persistence.SessionMarshallingHelper.loadSnapshot(SessionMarshallingHelper.java:95) ~[drools-persistence-jpa-6.3.0.Final.jar:6.3.0.Final] ... 12 common frames omitted {code} We have now created a broken session that can not be loaded anymore. I apologise for the complicated nature of this, but it wasn't quite straight forward to reproduce this issue. I am still not certain what is happening here and how to handle it. Currently I have to recreate everything from scratch since there is no way to fix the session at that point anymore. If you could advise me on how to work around this and or if I am somehow causing this issue myself, that would be wonderful :) On IRC it was mentioned that when there is an SQL exception I should probably reload the session anyway. Is that correct? Thanks, Artur -- This message was sent by Atlassian JIRA (v6.4.11#64026)