search

eclipse-ee4j / openmq

OpenMQ
https://projects.eclipse.org/projects/ee4j.openmq/
Other
49 stars 34 forks source link

JMS direct mode fails on concurrent writes to single topic when using distributed transactions. #385

Open glassfishrobot opened 7 years ago

glassfishrobot commented 7 years ago

From @glassfishrobot on January 17, 2015 22:15

When multiple threads write to single JMS topic (only tested with topic, but that might be true for the queues also), each in its own distributed transaction, the broker fails with an error like the one below:

Jan 17, 2015 10:13:51 PM com.sun.messaging.jms.ra.DirectXAResource validateAndSaveXidTransactionID
INFO: DXAR:start():Warning: XAResource with state COMPLETE received diff Xid for open txnId:switching transactionId:
DXAR  Xid=(GlobalTransactionID=[B@1d8256f1, BranchQualifier=[B@42963311) 
DXAR TXid=5598056773328087040
got   Xid=(GlobalTransactionID=[B@1c462fe0, BranchQualifier=[B@47c43f17) 
got  TXid=5598056773328088320
Jan 17, 2015 10:13:51 PM com.sun.messaging.jms.ra.DirectXAResource prepare
SEVERE: prepareTransaction (XA) on JMSService:jmsdirect failed for connectionId:5598056773326219776 due to Unknown JMSService server error ERROR: com.sun.messaging.jmq.jmsserver.util.BrokerException: Bad transaction state transition. Cannot perform operation PREPARE_TRANSACTION(56) (XAFlag=null) on a transaction in state STARTED(1).
Jan 17, 2015 10:13:51 PM com.sun.jts.CosTransactions.RegisteredResources distributePrepare
WARNING: JTS5031: Exception [java.lang.RuntimeException: javax.transaction.xa.XAException] on Resource [prepare] operation.
Jan 17, 2015 10:13:51 PM com.sun.messaging.jms.ra.DirectXAResource rollback
SEVERE: rollbackTransaction (XA) on JMSService:jmsdirect failed for connectionId:5598056773326219776:transactionId=5598056773328088320 due to Unknown JMSService server error ERROR: com.sun.messaging.jmq.jmsserver.util.BrokerException: Transaction XID mismatch 6A696767626F6F6B2E6C6F63616C2C7365727665722C503130302C013B0000004D8FBEF96A696767626F6F6B2E6C6F63616C2C7365727665722C50313030, expected 6A696767626F6F6B2E6C6F63616C2C7365727665722C503130302C013C0000004D8FBEF96A696767626F6F6B2E6C6F63616C2C7365727665722C50313030 for transaction 5598056773328088320
Jan 17, 2015 10:13:51 PM com.sun.jts.jtsxa.OTSResourceImpl rollback
WARNING: JTS5068: Unexpected error occurred in rollback
javax.transaction.xa.XAException
    at com.sun.messaging.jms.ra.DirectXAResource.rollback(DirectXAResource.java:738)
    at com.sun.messaging.jms.ra.DirectXAResource.rollback(DirectXAResource.java:689)
    at com.sun.jts.jta.TransactionState._rollback(TransactionState.java:202)
    at com.sun.jts.jta.TransactionState.rollback(TransactionState.java:180)
    at com.sun.jts.jtsxa.OTSResourceImpl.rollback(OTSResourceImpl.java:333)
    at com.sun.jts.CosTransactions.RegisteredResources.distributeRollback(RegisteredResources.java:1040)
    at com.sun.jts.CosTransactions.TopCoordinator.rollback(TopCoordinator.java:2291)
    at com.sun.jts.CosTransactions.CoordinatorTerm.commit(CoordinatorTerm.java:391)
    at com.sun.jts.CosTransactions.TerminatorImpl.commit(TerminatorImpl.java:231)
    at com.sun.jts.CosTransactions.CurrentImpl.commit(CurrentImpl.java:622)
    at com.sun.jts.jta.TransactionManagerImpl.commit(TransactionManagerImpl.java:331)
    at com.sun.enterprise.transaction.jts.JavaEETransactionManagerJTSDelegate.commitDistributedTransaction(JavaEETransactionManagerJTSDelegate.java:185)
    at com.sun.enterprise.transaction.JavaEETransactionManagerSimplified.commit(JavaEETransactionManagerSimplified.java:859)
    at com.sun.enterprise.transaction.UserTransactionImpl.commit(UserTransactionImpl.java:212)
    at com.ibm.jbatch.container.transaction.impl.JTAUserTransactionAdapter.commit(JTAUserTransactionAdapter.java:91)
    at com.ibm.jbatch.container.impl.ChunkStepControllerImpl.invokeChunk(ChunkStepControllerImpl.java:620)
    at com.ibm.jbatch.container.impl.ChunkStepControllerImpl.invokeCoreStep(ChunkStepControllerImpl.java:684)
    at com.ibm.jbatch.container.impl.BaseStepControllerImpl.execute(BaseStepControllerImpl.java:144)
    at com.ibm.jbatch.container.impl.ExecutionTransitioner.doExecutionLoop(ExecutionTransitioner.java:112)
    at com.ibm.jbatch.container.impl.JobThreadRootControllerImpl.originateExecutionOnThread(JobThreadRootControllerImpl.java:110)
    at com.ibm.jbatch.container.util.BatchWorkUnit.run(BatchWorkUnit.java:80)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at org.glassfish.enterprise.concurrent.internal.ManagedFutureTask.run(ManagedFutureTask.java:141)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
    at org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:250)
Caused by: com.sun.messaging.jmq.jmsservice.JMSServiceException: rollbackTransaction: rollback transaction failed. Connection ID: 5598056773326219776, Transaction ID: 5598056773328088320, XID: (Available at FINE log level) Caused by:com.sun.messaging.jmq.jmsserver.util.BrokerException: Transaction XID mismatch 6A696767626F6F6B2E6C6F63616C2C7365727665722C503130302C013B0000004D8FBEF96A696767626F6F6B2E6C6F63616C2C7365727665722C50313030, expected 6A696767626F6F6B2E6C6F63616C2C7365727665722C503130302C013C0000004D8FBEF96A696767626F6F6B2E6C6F63616C2C7365727665722C50313030 for transaction 5598056773328088320
    at com.sun.messaging.jmq.jmsserver.service.imq.JMSServiceImpl.rollbackTransaction(JMSServiceImpl.java:1718)
    at com.sun.messaging.jms.ra.DirectXAResource.rollback(DirectXAResource.java:714)
    ... 27 more
Caused by: com.sun.messaging.jmq.jmsserver.util.BrokerException: Transaction XID mismatch 6A696767626F6F6B2E6C6F63616C2C7365727665722C503130302C013B0000004D8FBEF96A696767626F6F6B2E6C6F63616C2C7365727665722C50313030, expected 6A696767626F6F6B2E6C6F63616C2C7365727665722C503130302C013C0000004D8FBEF96A696767626F6F6B2E6C6F63616C2C7365727665722C50313030 for transaction 5598056773328088320
    at com.sun.messaging.jmq.jmsserver.data.protocol.ProtocolImpl.rollbackTransaction(ProtocolImpl.java:921)
    at com.sun.messaging.jmq.jmsserver.service.imq.JMSServiceImpl.rollbackTransaction(JMSServiceImpl.java:1706)
    ... 28 more

I've created a test case that reproduces the issue quite repeatedly - it's available on github.

The test case consists of a batch job that contains a single chunk-style step with partition mapper (step's partitioned as the problem occurs in a concurrent environment). ItemReader creates random number (between MIN and MAX as defined in SimplePartitionMapper) of entity instances of type Subscriber. ItemProcessor does nothing, but sleeps for 50 ms. Item writer persists entities created by the reader and then publishes the collection of items to JMS topic (in a single distributed transaction) and here's where the problem occurs. Will try to provide the more detailed description of the test case in the README.md file on github.

Environment

Tested with glass fish-embedded on Windows 7 & Mac OSX 10.10.1

Affected Versions

[4.1]

Copied from original issue: javaee/glassfish#21289

glassfishrobot commented 6 years ago
glassfishrobot commented 7 years ago

@amykang2020 Commented From @glassfishrobot on March 11, 2015 18:8

stephanbauer7 said: Hi, I have the same problem with Queues in Glassfish 4.1. I am also using XA-Transactions.

Information:   11 Mrz 2015 10:55:53,039 [p: thread-pool-1; w: 3] DEBUG org.apache.ibatis.logging.jdbc.BaseJdbcLogger:132 - ==>  Preparing: delete from ACT_RU_EVENT_SUBSCR where ID_ = ? and REV_ = ?
Information:   11 Mrz 2015 10:55:53,039 [pool-22-thread-3] DEBUG org.activiti.engine.impl.db.DbSqlSession:828 - executing: delete JobEntity [id=42532]
Information:   11 Mrz 2015 10:55:53,039 [pool-22-thread-3] DEBUG org.apache.ibatis.logging.jdbc.BaseJdbcLogger:132 - ooo Using Connection [com.sun.gjc.spi.jdbc40.ConnectionWrapper40@4e70cf77]
Schwerwiegend:   commitTransaction (XA) on JMSService:jmsdirect failed for connectionId:6980944495603333120 and onePhase:true due to Unknown JMSService server error ERROR: com.sun.messaging.jmq.jmsserver.util.BrokerException: Transaction XID mismatch 6D75686861676C2C7365727665722C50333730302C000C000000660039086D75686861676C2C7365727665722C5033373030, expected 6D75686861676C2C7365727665722C50333730302C000B000000660039086D75686861676C2C7365727665722C5033373030 for transaction 6980944495768780544
Information:   11 Mrz 2015 10:55:53,039 [p: thread-pool-1; w: 3] DEBUG org.apache.ibatis.logging.jdbc.BaseJdbcLogger:132 - ==> Parameters: 40068(String), 1(Integer)
Information:   11 Mrz 2015 10:55:53,039 [pool-22-thread-3] DEBUG org.apache.ibatis.logging.jdbc.BaseJdbcLogger:132 - ==>  Preparing: delete from ACT_RU_JOB where ID_ = ? and REV_ = ?
Schwerwiegend:   rollbackTransaction (XA) on JMSService:jmsdirect failed for connectionId:6980944495603333120:transactionId=6980944495768780544 due to Unknown JMSService server error ERROR: com.sun.messaging.jmq.jmsserver.util.BrokerException: Transaction XID mismatch 6D75686861676C2C7365727665722C50333730302C000C000000660039086D75686861676C2C7365727665722C5033373030, expected 6D75686861676C2C7365727665722C50333730302C000B000000660039086D75686861676C2C7365727665722C5033373030 for transaction 6980944495768780544
Information:   11 Mrz 2015 10:55:53,040 [p: thread-pool-1; w: 3] DEBUG org.apache.ibatis.logging.jdbc.BaseJdbcLogger:132 - <==    Updates: 1
glassfishrobot commented 7 years ago

@amykang2020 Commented From @glassfishrobot on March 11, 2015 18:20

@amykang2020 said: Assuming the test case follows the JMS and Java EE spec (haven't looked at it myself) in using transaction, JMS Session, JMSContext etc., I suspect this is likely an issue with jms-service DIRECT (or EMBEDDED) mode for it uses a completely different path in JMSRA to interact with broker. I'd suggest first check the test case to ensure spec compliance, then try jms-service LOCAL mode.

glassfishrobot commented 7 years ago

@amykang2020 Commented From @glassfishrobot on April 21, 2017 8:42

This issue was imported from java.net JIRA GLASSFISH-21289

glassfishrobot commented 7 years ago

@amykang2020 Commented From @glassfishrobot on January 17, 2015 22:15

Reported by jiggster

glassfishrobot commented 7 years ago

@amykang2020 Commented This appears to be an issue in JMSRA direct mode. A further evaluation is needed although not a must fix for GlassFish 5.0 RI

glassfishrobot commented 7 years ago

@nigeldeakin Commented Nice test case. I ran it repeatedly (using mvn clean test) and it passed every time. Here's an example of the test output: test.out.txt

I'm evaluating this issue for GlassFish 5.0 (MQ 5.1.1). Since this is a RI release, I need to consider whether or not this issue prevents GlassFish functioning as a RI. The fact that the issue was not seen when running the test case here suggests that the issue is intermittent and does not prevent it being used as a RI. I am therefore excluding it from 5.0.

I'll leave the issue open for now; if @jiggster or anyone would like to provide an updated test case this will be considered for a later release.

hberton commented 2 years ago

Same problem in Glassfish 5.1 with MQ 5.1.3

pzygielo commented 2 years ago

Same problem in Glassfish 5.1 with MQ 5.1.3

@hberton please provide reproducer (or update https://github.com/jigga/xid-mismatch from original report, which is not runnable/got outdated).