Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
glassfishrobot opened this issue Jul 2, 2017 · 9 comments
Open

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

glassfishrobot opened this issue Jul 2, 2017 · 9 comments
Labels
bug Something isn't working Component: mq-ra Priority: Critical Type: Bug

Comments

@glassfishrobot
Copy link

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
Copy link
Author

@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
Copy link
Author

@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
Copy link
Author

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

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

@glassfishrobot
Copy link
Author

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

Reported by jiggster

@glassfishrobot
Copy link
Author

@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
Copy link
Author

@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.

@glassfishrobot
Copy link
Author

@glassfishrobot glassfishrobot added this to the 5.1.1-next milestone Feb 10, 2018
@keilw keilw added the bug Something isn't working label Jul 6, 2018
@keilw keilw removed 4-0-b78 labels Oct 1, 2018
@pzygielo pzygielo removed this from the 5.1.2 milestone Jan 9, 2021
@hberton
Copy link

hberton commented Jan 14, 2022

Same problem in Glassfish 5.1 with MQ 5.1.3

@pzygielo
Copy link
Contributor

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).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working Component: mq-ra Priority: Critical Type: Bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@keilw @glassfishrobot @pzygielo @hberton