Recently, the move of a large Java EE application from Oracle 12c to MS SQL Server 2016 has begun. Most of the functionality has been tested for smoke to work fine, including Quartz Scheduler, basic JMS, Hibernate and EJB functions that work fine, etc. One strange problem slowed progress, so hoping someone might have a suggestion.
The jBPM console works for logging in and starting / pausing / stopping tasks. There is a situation that always causes an error. The jBPM task can be signaled using the console, and it starts fine, but as soon as the first task is completed and the application code tries to pass a token in order to proceed to the next task, the code always crashes with an error.
This code worked, of course, with Oracle with xa-datasource configured.
Error: ( full stacktrace )
2017-10-13 16:03:31,463 [WorkManager(2)-19] DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection 2017-10-13 16:03:31,464 [WorkManager(2)-19] DEBUG [org.hibernate.util.JDBCExceptionReporter] Cannot open connection [???] org.jboss.util.NestedSQLException: Transaction is not active: tx=TransactionImple < ac, BasicAction: -71740de1:d47b:59e10d94:f5 status: ActionStatus.ABORT_ONLY >; - nested throwable: (javax.resource.ResourceException: Transaction is not active: tx=TransactionImple < ac, BasicAction: -71740de1:d47b:59e10d94:f5 status: ActionStatus.ABORT_ONLY >) at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:95) at org.hibernate.connection.DatasourceConnectionProvider.getConnection(DatasourceConnectionProvider.java:69) at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:423) at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144) at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:139) at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1547) at org.hibernate.loader.Loader.doQuery(Loader.java:673) at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:236) at org.hibernate.loader.Loader.loadEntity(Loader.java:1860) at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:48) at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:42) at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3044) at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:395) at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:375) at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:139) at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:195) at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:103) at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:878) at org.hibernate.impl.SessionImpl.get(SessionImpl.java:815) at org.hibernate.impl.SessionImpl.get(SessionImpl.java:808) at org.jbpm.db.GraphSession.getToken(GraphSession.java:338) at org.jbpm.JbpmContext.getToken(JbpmContext.java:286) at ca.gnb.medicare.process.handling.ProcessUtilBean.signal(ProcessUtilBean.java:47) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:112) at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:166) at ca.gnb.medicare.service.interceptors.PeristenceContextInterceptor.intercept(PeristenceContextInterceptor.java:41) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:118) at org.jboss.ejb3.interceptor.EJB3InterceptorsInterceptor.invoke(EJB3InterceptorsInterceptor.java:63) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:54) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:79) at org.jboss.aspects.tx.TxInterceptor$RequiresNew.invoke(TxInterceptor.java:253) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:95) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:62) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:77) at org.jboss.ejb3.security.Ejb3AuthenticationInterceptor.invoke(Ejb3AuthenticationInterceptor.java:110) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:46) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.asynchronous.AsynchronousInterceptor.invoke(AsynchronousInterceptor.java:106) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.stateless.StatelessContainer.localInvoke(StatelessContainer.java:240) at org.jboss.ejb3.stateless.StatelessContainer.localInvoke(StatelessContainer.java:210) at org.jboss.ejb3.stateless.StatelessLocalProxy.invoke(StatelessLocalProxy.java:84) at com.sun.proxy.$Proxy155.signal(Unknown Source) at ca.gnb.medicare.service.util.AbstractServiceActivator.onMessage(AbstractServiceActivator.java:143) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:112) at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:166) at ca.gnb.medicare.service.interceptors.PeristenceContextInterceptor.intercept(PeristenceContextInterceptor.java:41) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:118) at org.jboss.ejb3.interceptor.EJB3InterceptorsInterceptor.invoke(EJB3InterceptorsInterceptor.java:63) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:54) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.aspects.tx.TxPolicy.invokeInCallerTx(TxPolicy.java:126) at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:195) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:62) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.mdb.MessagingContainer.localInvoke(MessagingContainer.java:249) at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.delivery(MessageInflowLocalProxy.java:268) at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.invoke(MessageInflowLocalProxy.java:138) at com.sun.proxy.$Proxy169.onMessage(Unknown Source) at org.jboss.resource.adapter.jms.inflow.JmsServerSession.onMessage(JmsServerSession.java:178) at org.jboss.mq.SpyMessageConsumer.sessionConsumerProcessMessage(SpyMessageConsumer.java:906) at org.jboss.mq.SpyMessageConsumer.addMessage(SpyMessageConsumer.java:170) at org.jboss.mq.SpySession.run(SpySession.java:323) at org.jboss.resource.adapter.jms.inflow.JmsServerSession.run(JmsServerSession.java:237) at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:204) at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:275) at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:756) at java.lang.Thread.run(Unknown Source) Caused by: javax.resource.ResourceException: Transaction is not active: tx=TransactionImple < ac, BasicAction: -71740de1:d47b:59e10d94:f5 status: ActionStatus.ABORT_ONLY > at org.jboss.resource.connectionmanager.TxConnectionManager.getManagedConnection(TxConnectionManager.java:319)
I canβt imagine how SQL Server affects a transaction.
We also get this error on SQL Server: ( full sql dump )
2017-10-11 13:10:53.44 spid61 ***Stack Dump being sent to G:\MedSt\MSSQL13.MEDST\MSSQL\LOG\SQLDump0032.txt 2017-10-11 13:10:53.44 spid61 SqlDumpExceptionHandler: Process 61 generated fatal exception c0000005 EXCEPTION_ACCESS_VIOLATION. SQL Server is terminating this process. 2017-10-11 13:10:54.15 spid61 External dump process return code 0x20000001. External dump process returned no errors. 2017-10-11 13:10:54.15 spid61 Error: 18002, Severity: 20, State: 1. 2017-10-11 13:10:54.15 spid61 Exception happened when running extended stored procedure 'xp_sqljdbc_xa_start' in the library 'SQLJDBC_XA.dll'. SQL Server is terminating process 61. Exception type: Win32 exception; Exception code: 0xc0000005.
Error code:
@Stateless public class ProcessUtilBean implements ProcessUtil{ private static Logger log = Logger.getLogger(); @EJB DecrementWorkCounter decrementWorkCounter; @TransactionAttribute(TransactionAttributeType.REQUIRES_NEW) public void signal(long tokenId){ JbpmContext context = null; try { context = getJbpmContext(); log.info("attempting to get token (" + tokenId + ")"); Token token; token = context.getToken(tokenId); token.signal();
There are, of course, several tons of XML, but I have changed a bit. Basically, only data sources were changed, SQL Dialect and copied by mssql-jdbc2-service.xml from the jboss sample folder.
Here is a jms-ds.xml example, as errors somewhat indicate a problem here with JMS:
<?xml version="1.0" encoding="UTF-8"?> <connection-factories> <mbean code="org.jboss.jms.jndi.JMSProviderLoader" name="jboss.mq:service=JMSProviderLoader,name=JMSProvider"> <attribute name="ProviderName">DefaultJMSProvider</attribute> <attribute name="ProviderAdapterClass"> org.jboss.jms.jndi.JNDIProviderAdapter </attribute> <attribute name="FactoryRef">java:/XAConnectionFactory</attribute> <attribute name="QueueFactoryRef">java:/XAConnectionFactory</attribute> <attribute name="TopicFactoryRef">java:/XAConnectionFactory</attribute> </mbean> <mbean code="org.jboss.jms.asf.ServerSessionPoolLoader" name="jboss.mq:service=ServerSessionPoolMBean,name=StdJMSPool"> <depends optional-attribute-name="XidFactory">jboss:service=XidFactory</depends> <attribute name="PoolName">StdJMSPool</attribute> <attribute name="PoolFactoryClass"> org.jboss.jms.asf.StdServerSessionPoolFactory </attribute> </mbean> <tx-connection-factory> <jndi-name>JmsXA</jndi-name> <xa-transaction/> <rar-name>jms-ra.rar</rar-name> <connection-definition>org.jboss.resource.adapter.jms.JmsConnectionFactory</connection-definition> <config-property name="SessionDefaultType" type="java.lang.String">javax.jms.Topic</config-property> <config-property name="JmsProviderAdapterJNDI" type="java.lang.String">java:/DefaultJMSProvider</config-property> <security-domain-and-application>JmsXARealm</security-domain-and-application> <max-pool-size>20</max-pool-size> </tx-connection-factory> </connection-factories>
Versions:
- Java 1.7
- jboss 4.2.3.GA
- jbpm 3.2.6.sp1
- hibernate 3.2.4.sp1
(I know someone will comment, so yes, these are all the graphs that need to be updated)
SQL drivers so far:
- sqljdbc_4.0.2206.100_enu
- MSSQL-JDBC-6.2.1.jre7
- MSSQL-JDBC-6.2.2.jre7
- MSSQL-JDBC-6.3.3.jre7 view
- We have followed the directions of Transaction XA published
If I missed something important, I will add it.
** edit **
Finally, another piece of information came from the SQL driver.
2017-10-18 14:03:31,096 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.TDSReader readBytes FINEST: TDSReader@370 (ConnectionID:166 ClientConnectionId: a62ad6a5-19e4-4187-83f5-c60a6bb1aaad) Reading 44 bytes from offset 334 2017-10-18 14:03:31,098 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.TDSParser parse FINEST: TDSReader@370 (ConnectionID:166 ClientConnectionId: a62ad6a5-19e4-4187-83f5-c60a6bb1aaad): logon: Processing TDS_ENV_CHG (0xE3) 2017-10-18 14:03:31,098 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.TDSReader mark FINEST: TDSReader@370 (ConnectionID:166 ClientConnectionId: a62ad6a5-19e4-4187-83f5-c60a6bb1aaad): Buffering from: com.microsoft.sqlserver.jdbc.TDSReaderMark@6b6611f0 2017-10-18 14:03:31,098 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.TDSReader readBytes FINEST: TDSReader@370 (ConnectionID:166 ClientConnectionId: a62ad6a5-19e4-4187-83f5-c60a6bb1aaad) Reading 8 bytes from offset 387 2017-10-18 14:03:31,099 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.SQLServerConnection processEnvChange FINER: ConnectionID:166 ClientConnectionId: a62ad6a5-19e4-4187-83f5-c60a6bb1aaad Network packet size is 8000 bytes 2017-10-18 14:03:31,099 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.TDSReader reset FINEST: TDSReader@370 (ConnectionID:166 ClientConnectionId: a62ad6a5-19e4-4187-83f5-c60a6bb1aaad): Resetting to: com.microsoft.sqlserver.jdbc.TDSReaderMark@6b6611f0 2017-10-18 14:03:31,099 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.TDSReader readBytes FINEST: TDSReader@370 (ConnectionID:166 ClientConnectionId: a62ad6a5-19e4-4187-83f5-c60a6bb1aaad) Reading 19 bytes from offset 385 2017-10-18 14:03:31,099 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.TDSParser parse FINEST: TDSReader@370 (ConnectionID:166 ClientConnectionId: a62ad6a5-19e4-4187-83f5-c60a6bb1aaad): logon: Processing TDS_DONE (0xFD) 2017-10-18 14:03:31,099 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.TDSParser parse FINEST: TDSReader@370 (ConnectionID:166 ClientConnectionId: a62ad6a5-19e4-4187-83f5-c60a6bb1aaad): logon: Processing EOF 2017-10-18 14:03:31,100 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.SQLServerConnection connectInternal FINER: ConnectionID:166 ClientConnectionId: a62ad6a5-19e4-4187-83f5-c60a6bb1aaad End of connect 2017-10-18 14:03:31,100 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.SQLServerXAConnection <init> FINER: Created an internal control connectionConnectionID:166 ClientConnectionId: a62ad6a5-19e4-4187-83f5-c60a6bb1aaad for SQLServerXAConnection:81 Physical connection:ConnectionID:165 ClientConnectionId: 78fd8cb2-78ff-44d7-9cae-e20e6256b37e 2017-10-18 14:03:31,100 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.SQLServerXAConnection <init> FINER: SQLServerXADataSource:1 user:MEDST3 2017-10-18 14:03:31,100 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.SQLServerXADataSource getXAConnection FINER: SQLServerXADataSource:1 user:MEDST3SQLServerXAConnection:81 2017-10-18 14:03:31,100 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.SQLServerXADataSource getXAConnection FINER: SQLServerXADataSource:1 Start get physical connection. 2017-10-18 14:03:31,100 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.SQLServerXADataSource getXAConnection FINE: SQLServerXADataSource:1 End get physical connection, ConnectionID:165 ClientConnectionId: 78fd8cb2-78ff-44d7-9cae-e20e6256b37e 2017-10-18 14:03:31,100 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.SQLServerXADataSource:1 getXAConnection FINER: RETURN SQLServerXAConnection:81 2017-10-18 14:03:31,101 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.SQLServerPooledConnection getConnection FINER: SQLServerXAConnection:81 user:(default). 2017-10-18 14:03:31,101 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.SQLServerPooledConnection getConnection FINE: SQLServerXAConnection:81 Physical connection, ConnectionID:165 ClientConnectionId: 78fd8cb2-78ff-44d7-9cae-e20e6256b37e 2017-10-18 14:03:31,098 [main] TRACE [org.jboss.web.tomcat.service.WebAppClassLoader] filter name=ca.gnb.medicare.application.claim.manage.SelectServiceProvider$1, exclude=false 2017-10-18 14:03:31,101 [main] DEBUG [org.apache.catalina.loader.WebappClassLoader] Searching local repositories 2017-10-18 14:03:31,101 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.SQLServerPooledConnection getConnection FINE: SQLServerXAConnection:81 proxy ProxyConnectionID:81 is returned. 2017-10-18 14:03:31,101 [main] TRACE [org.jboss.web.tomcat.service.WebAppClassLoader] findClass(ca.gnb.medicare.application.claim.manage.SelectServiceProvider$1) called 2017-10-18 14:03:31,101 [main] DEBUG [org.apache.catalina.loader.WebappClassLoader] findClass(ca.gnb.medicare.application.claim.manage.SelectServiceProvider$1) 2017-10-18 14:03:31,101 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.SQLServerConnection:165 getTransactionIsolation FINER: ENTRY 2017-10-18 14:03:31,101 [main] TRACE [org.apache.catalina.loader.WebappClassLoader] findClassInternal(ca.gnb.medicare.application.claim.manage.SelectServiceProvider$1) 2017-10-18 14:03:31,101 [WorkManager(2)-19] INFO [org.hibernate.impl.SessionFactoryImpl] building session factory 2017-10-18 14:03:31,101 [JCA PoolFiller] ERROR [STDERR] Oct 18, 2017 2:03:31 PM com.microsoft.sqlserver.jdbc.SQLServerConnection:165 getTransactionIsolation FINER: RETURN 2 (this is = TRANSACTION_READ_COMMITTED) https://docs.oracle.com/javase/7/docs/api/constant-values.html