Completed process instances' records are not removed from ProcessInstanceLog table in jBPM 5

Issue

• While executing a process instance in Business Central throws the following exception on the console.

org.jboss.resteasy.spi.UnhandledException: java.lang.RuntimeException: Could not commit session or rollback
    org.jboss.resteasy.core.SynchronousDispatcher.unwrapException(SynchronousDispatcher.java:345)
    org.jboss.resteasy.core.SynchronousDispatcher.handleApplicationException(SynchronousDispatcher.java:321)
    org.jboss.resteasy.core.SynchronousDispatcher.handleException(SynchronousDispatcher.java:214)
    org.jboss.resteasy.core.SynchronousDispatcher.handleInvokerException(SynchronousDispatcher.java:190)
    org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:534)
    org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:496)
    org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:119)
    org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:208)
    org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:55)
    org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:50)
    javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
    org.jboss.bpm.console.server.util.GWTJsonFilter.doFilter(GWTJsonFilter.java:59)
    org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)

...

• The issue is taking place when a process instance is completed and it's record is removed from processinstanceinfo table but inside processinstancelog table the entry remains without having any value for end_date column. That results in the entry for the process instance still visible in process overview section of Business Central console. Now, if it is attempted to create another process instance, sometimes it doesn't allow to do so. The following log entries reveals the chain of actions taking place during such an event.

2014-02-03 14:00:06,360 DEBUG [org.hibernate.pretty.Printer] (http-127.0.0.1-8080-3) listing entities:
2014-02-03 14:00:06,360 DEBUG [org.hibernate.pretty.Printer] (http-127.0.0.1-8080-3) org.jbpm.process.audit.NodeInstanceLog{id=5, nodeId=1, processInstanceId=2, processId=defaultPackage.Test, nodeName=Start, type=1, nodeInstanceId=0, date=2014-02-03 14:00:06}
2014-02-03 14:00:06,361 DEBUG [org.hibernate.pretty.Printer] (http-127.0.0.1-8080-3) org.jbpm.process.audit.NodeInstanceLog{id=6, nodeId=2, processInstanceId=2, processId=defaultPackage.Test, nodeName=Script, type=0, nodeInstanceId=1, date=2014-02-03 14:00:06}
2014-02-03 14:00:06,361 DEBUG [org.hibernate.pretty.Printer] (http-127.0.0.1-8080-3) org.jbpm.process.audit.NodeInstanceLog{id=4, nodeId=1, processInstanceId=2, processId=defaultPackage.Test, nodeName=Start, type=0, nodeInstanceId=0, date=2014-02-03 14:00:06}
2014-02-03 14:00:06,361 DEBUG [org.hibernate.pretty.Printer] (http-127.0.0.1-8080-3) org.jbpm.process.audit.NodeInstanceLog{id=9, nodeId=3, processInstanceId=2, processId=defaultPackage.Test, nodeName=End, type=1, nodeInstanceId=2, date=2014-02-03 14:00:06}
2014-02-03 14:00:06,361 DEBUG [org.hibernate.pretty.Printer] (http-127.0.0.1-8080-3) org.jbpm.process.audit.NodeInstanceLog{id=7, nodeId=2, processInstanceId=2, processId=defaultPackage.Test, nodeName=Script, type=1, nodeInstanceId=1, date=2014-02-03 14:00:06}
2014-02-03 14:00:06,361 DEBUG [org.hibernate.pretty.Printer] (http-127.0.0.1-8080-3) org.jbpm.process.audit.NodeInstanceLog{id=8, nodeId=3, processInstanceId=2, processId=defaultPackage.Test, nodeName=End, type=0, nodeInstanceId=2, date=2014-02-03 14:00:06}
2014-02-03 14:00:06,361 DEBUG [org.hibernate.pretty.Printer] (http-127.0.0.1-8080-3) org.jbpm.process.audit.ProcessInstanceLog{id=3, processInstanceId=2, start=2014-02-03 14:00:06, processId=defaultPackage.Test, end=null}
2014-02-03 14:00:06,362 DEBUG [org.hibernate.pretty.Printer] (http-127.0.0.1-8080-3) org.jbpm.persistence.processinstance.ProcessInstanceInfo{startDate=2014-02-03 14:00:06, processInstanceId=2, processId=defaultPackage.Test, processInstanceByteArray=null, state=0, lastModificationDate=null, eventTypes=[], lastReadDate=2014-02-03 14:00:06, version=0}
2014-02-03 14:00:06,362 DEBUG [org.hibernate.jdbc.AbstractBatcher] (http-127.0.0.1-8080-3) about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2014-02-03 14:00:06,362 DEBUG [org.hibernate.jdbc.ConnectionManager] (http-127.0.0.1-8080-3) opening JDBC connection
2014-02-03 14:00:06,362 DEBUG [org.hibernate.SQL] (http-127.0.0.1-8080-3) insert into ProcessInstanceInfo (OPTLOCK, processId, startDate, lastReadDate, lastModificationDate, state, processInstanceByteArray, InstanceId) values (?, ?, ?, ?, ?, ?, ?, ?)
2014-02-03 14:00:06,362 DEBUG [org.hibernate.jdbc.AbstractBatcher] (http-127.0.0.1-8080-3) Executing batch size: 1
2014-02-03 14:00:06,363 DEBUG [org.hibernate.jdbc.AbstractBatcher] (http-127.0.0.1-8080-3) about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2014-02-03 14:00:06,363 DEBUG [org.hibernate.jdbc.ConnectionManager] (http-127.0.0.1-8080-3) skipping aggressive-release due to flush cycle
2014-02-03 14:00:06,363 DEBUG [org.hibernate.jdbc.AbstractBatcher] (http-127.0.0.1-8080-3) about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2014-02-03 14:00:06,363 DEBUG [org.hibernate.SQL] (http-127.0.0.1-8080-3) insert into ProcessInstanceLog (end_date, processId, processInstanceId, start_date, id) values (?, ?, ?, ?, ?)
2014-02-03 14:00:06,363 DEBUG [org.hibernate.jdbc.AbstractBatcher] (http-127.0.0.1-8080-3) Executing batch size: 1
2014-02-03 14:00:06,365 DEBUG [org.hibernate.jdbc.AbstractBatcher] (http-127.0.0.1-8080-3) about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2014-02-03 14:00:06,365 DEBUG [org.hibernate.jdbc.ConnectionManager] (http-127.0.0.1-8080-3) skipping aggressive-release due to flush cycle
2014-02-03 14:00:06,365 DEBUG [org.hibernate.jdbc.AbstractBatcher] (http-127.0.0.1-8080-3) about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2014-02-03 14:00:06,365 DEBUG [org.hibernate.SQL] (http-127.0.0.1-8080-3) insert into NodeInstanceLog (log_date, nodeId, nodeInstanceId, nodeName, processId, processInstanceId, type, id) values (?, ?, ?, ?, ?, ?, ?, ?)
2014-02-03 14:00:06,365 DEBUG [org.hibernate.jdbc.AbstractBatcher] (http-127.0.0.1-8080-3) reusing prepared statement
2014-02-03 14:00:06,365 DEBUG [org.hibernate.SQL] (http-127.0.0.1-8080-3) insert into NodeInstanceLog (log_date, nodeId, nodeInstanceId, nodeName, processId, processInstanceId, type, id) values (?, ?, ?, ?, ?, ?, ?, ?)
2014-02-03 14:00:06,365 DEBUG [org.hibernate.jdbc.AbstractBatcher] (http-127.0.0.1-8080-3) reusing prepared statement
2014-02-03 14:00:06,365 DEBUG [org.hibernate.SQL] (http-127.0.0.1-8080-3) insert into NodeInstanceLog (log_date, nodeId, nodeInstanceId, nodeName, processId, processInstanceId, type, id) values (?, ?, ?, ?, ?, ?, ?, ?)
2014-02-03 14:00:06,365 DEBUG [org.hibernate.jdbc.AbstractBatcher] (http-127.0.0.1-8080-3) reusing prepared statement
2014-02-03 14:00:06,365 DEBUG [org.hibernate.SQL] (http-127.0.0.1-8080-3) insert into NodeInstanceLog (log_date, nodeId, nodeInstanceId, nodeName, processId, processInstanceId, type, id) values (?, ?, ?, ?, ?, ?, ?, ?)
2014-02-03 14:00:06,366 DEBUG [org.hibernate.jdbc.AbstractBatcher] (http-127.0.0.1-8080-3) reusing prepared statement
2014-02-03 14:00:06,366 DEBUG [org.hibernate.SQL] (http-127.0.0.1-8080-3) insert into NodeInstanceLog (log_date, nodeId, nodeInstanceId, nodeName, processId, processInstanceId, type, id) values (?, ?, ?, ?, ?, ?, ?, ?)
2014-02-03 14:00:06,366 DEBUG [org.hibernate.jdbc.AbstractBatcher] (http-127.0.0.1-8080-3) reusing prepared statement
2014-02-03 14:00:06,366 DEBUG [org.hibernate.SQL] (http-127.0.0.1-8080-3) insert into NodeInstanceLog (log_date, nodeId, nodeInstanceId, nodeName, processId, processInstanceId, type, id) values (?, ?, ?, ?, ?, ?, ?, ?)
2014-02-03 14:00:06,366 DEBUG [org.hibernate.jdbc.AbstractBatcher] (http-127.0.0.1-8080-3) Executing batch size: 6
2014-02-03 14:00:06,369 DEBUG [org.hibernate.jdbc.AbstractBatcher] (http-127.0.0.1-8080-3) about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2014-02-03 14:00:06,369 DEBUG [org.hibernate.jdbc.ConnectionManager] (http-127.0.0.1-8080-3) skipping aggressive-release due to flush cycle
2014-02-03 14:00:06,369 DEBUG [org.hibernate.jdbc.AbstractBatcher] (http-127.0.0.1-8080-3) about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2014-02-03 14:00:06,369 DEBUG [org.hibernate.SQL] (http-127.0.0.1-8080-3) delete from ProcessInstanceInfo where InstanceId=? and OPTLOCK=?