Details
-
Type:
Bug
-
Status:
Closed
-
Priority:
Major
-
Resolution: Fixed
-
Affects Version/s: 1.4.4, 2.0.0-RC2
-
Fix Version/s: 2.0.2
-
Component/s: Transport: VM
-
Labels:None
-
User impact:High
-
Configuration:Hide
<?xml version="1.0" encoding="UTF-8"?> <!DOCTYPE mule-configuration PUBLIC "-//MuleSource //DTD mule-configuration XML V1.0//EN" "http://mule.mulesource.org/dtds/mule-configuration.dtd"> <mule-configuration id="test" version="1.0"> <mule-environment-properties serverUrl=""/> <connector name="vm" className="org.mule.providers.vm.VMConnector"> <properties> <property name="queueEvents" value="true"/> </properties> </connector> <model name="main"> <mule-descriptor name="test" implementation="org.mule.providers.vm.functional.VmTransactionTestCase$TestComponent"> <inbound-router> <endpoint address="vm://in"> <transaction action="BEGIN_OR_JOIN" factory="org.mule.providers.vm.VMTransactionFactory"/> </endpoint> </inbound-router> <outbound-router> <router className="org.mule.routing.outbound.OutboundPassThroughRouter"> <endpoint address="vm://out"/> </router> </outbound-router> </mule-descriptor> </model> </mule-configuration>
Show<?xml version="1.0" encoding="UTF-8"?> <!DOCTYPE mule-configuration PUBLIC "-//MuleSource //DTD mule-configuration XML V1.0//EN" "http://mule.mulesource.org/dtds/mule-configuration.dtd"> <mule-configuration id="test" version="1.0"> <mule-environment-properties serverUrl=""/> <connector name="vm" className="org.mule.providers.vm.VMConnector"> <properties> <property name="queueEvents" value="true"/> </properties> </connector> <model name="main"> <mule-descriptor name="test" implementation="org.mule.providers.vm.functional.VmTransactionTestCase$TestComponent"> <inbound-router> <endpoint address="vm://in"> <transaction action="BEGIN_OR_JOIN" factory="org.mule.providers.vm.VMTransactionFactory"/> </endpoint> </inbound-router> <outbound-router> <router className="org.mule.routing.outbound.OutboundPassThroughRouter"> <endpoint address="vm://out"/> </router> </outbound-router> </mule-descriptor> </model> </mule-configuration>
-
Log Output:Hide[01-16 23:52:58] DEBUG Base64Encoder [main]: Object after transform: SUQ9MDQ4YzE4MWUtYzQ3NS0xMWRjLWFmNGYtY2QyOGJhMTljMjUz
[01-16 23:52:58] DEBUG Base64Encoder [main]: The transformed object is of expected type. Type is: String
[01-16 23:52:58] DEBUG VMConnector [main]: Borrowing a dispatcher for endpoint: vm://in
[01-16 23:52:58] DEBUG ObjectToByteArray [main]: java.lang.Object has been added as source type for this transformer, there will be no source type checking performed
[01-16 23:52:58] DEBUG VMConnector [main]: Borrowed dispatcher: VMMessageDispatcher{this=7c3885, endpoint=vm://in}
[01-16 23:52:58] DEBUG MuleMessage [main]: new copy of message for Thread[main,5,main]
[01-16 23:52:58] DEBUG VMConnector [main]: Returning dispatcher for endpoint: vm://in = VMMessageDispatcher{this=7c3885, endpoint=vm://in}
[01-16 23:52:58] DEBUG MuleMessage [vm.dispatcher.1]: new copy of message for Thread[vm.dispatcher.1,5,main]
[01-16 23:52:58] DEBUG TransportServiceDescriptor [main]: Loading endpointUri resolver: org.mule.impl.endpoint.ResourceNameEndpointBuilder
[01-16 23:52:58] DEBUG VMMessageDispatcher [vm.dispatcher.1]: Connecting: VMMessageDispatcher{this=7c3885, endpoint=vm://in}
[01-16 23:52:58] DEBUG VMConnector [main]: Borrowing a dispatcher for endpoint: vm://out
[01-16 23:52:58] INFO VMMessageDispatcher [vm.dispatcher.1]: Connected: VMMessageDispatcher{this=7c3885, endpoint=vm://in}
[01-16 23:52:58] DEBUG ObjectToByteArray [main]: java.lang.Object has been added as source type for this transformer, there will be no source type checking performed
[01-16 23:52:58] DEBUG VMConnector [vm.dispatcher.1]: Retrieving new VM queue session from queue manager
[01-16 23:52:58] DEBUG VMConnector [main]: Borrowed dispatcher: VMMessageDispatcher{this=3257b8, endpoint=vm://out}
[01-16 23:52:58] DEBUG VMMessageDispatcher [main]: Connecting: VMMessageDispatcher{this=3257b8, endpoint=vm://out}
[01-16 23:52:58] DEBUG VMMessageDispatcher [vm.dispatcher.1]: dispatched Event on endpointUri: vm://in
[01-16 23:52:58] INFO VMMessageDispatcher [main]: Connected: VMMessageDispatcher{this=3257b8, endpoint=vm://out}
[01-16 23:52:58] DEBUG VMConnector [main]: Retrieving new VM queue session from queue manager
[01-16 23:52:58] DEBUG VMMessageDispatcher [main]: Waiting for a message on out
[01-16 23:52:59] DEBUG TransactionTemplate [vm.receiver.1]: Beginning transaction
[01-16 23:52:59] DEBUG VMTransaction [vm.receiver.1]: Beginning transaction
[01-16 23:52:59] DEBUG TransactionalQueueManager [vm.receiver.1]: Beginning transaction 051b11b2-c475-11dc-af4f-cd28ba19c253[no transaction, readonly]
[01-16 23:52:59] DEBUG TransactionalQueueManager [vm.receiver.1]: Began transaction 051b11b2-c475-11dc-af4f-cd28ba19c253[active, readonly]
[01-16 23:52:59] DEBUG TransactionCoordination [vm.receiver.1]: Binding new transaction (1) org.mule.providers.vm.VMTransaction@1318b
[01-16 23:52:59] DEBUG TransactionTemplate [vm.receiver.1]: Transaction successfully started
[01-16 23:52:59] DEBUG VMConnector [vm.receiver.1]: Retrieved VM queue session org.mule.util.queue.TransactionalQueueSession@5bb966 from current transaction org.mule.providers.vm.VMTransaction@1318b
[01-16 23:53:08] DEBUG VMMessageDispatcher [main]: No event received after 10000 ms
------------------
[01-16 23:56:28] INFO TransactionalQueueManager [main]: Stopping ResourceManager
[01-16 23:56:28] INFO TransactionalQueueManager [main]: Waiting for tx 7c9836b5-c475-11dc-ad34-09ec0a840d00[active] to finish for 10000 milli seconds
[01-16 23:56:38] WARN TransactionalQueueManager [main]: Tx 7c9836b5-c475-11dc-ad34-09ec0a840d00[active] failed to finish in given time
[01-16 23:56:38] WARN TransactionalQueueManager [main]: Failed to stop ResourceManager
[01-16 23:56:38] INFO VMConnector [main]: Removing listener on endpointUri: vm://in
[01-16 23:56:38] INFO SedaModel [main]: Component test has been stopped successfully
[01-16 23:56:38] INFO VMConnector [main]: Disposing: VMConnector{this=ab444, started=false, initialised=false, name='vm', disposed=false, numberOfConcurrentTransactedReceivers=1, createMultipleTransactedReceivers=true, connected=false, supportedProtocols=[vm], serviceOverrides=null}
[01-16 23:56:38] INFO VMConnector [main]: Stopped: VMConnector{this=ab444, started=false, initialised=false, name='vm', disposed=false, numberOfConcurrentTransactedReceivers=1, createMultipleTransactedReceivers=true, connected=false, supportedProtocols=[vm], serviceOverrides=null}
[01-16 23:56:38] INFO VMMessageDispatcher [main]: Disconnected: VMMessageDispatcher{this=ff94b1, endpoint=vm://in}
[01-16 23:56:38] INFO VMMessageDispatcher [main]: Disconnected: VMMessageDispatcher{this=edf730, endpoint=vm://out}
[01-16 23:56:38] INFO TransactionTemplate [vm.receiver.1]: Exception Caught in Transaction template. Handing off to exception handler: org.mule.impl.DefaultExceptionStrategy@ab54eb
[01-16 23:56:38] ERROR DefaultExceptionStrategy [vm.receiver.1]: Caught exception in Exception Strategy: null
java.lang.InterruptedException
at java.lang.Object.wait(Native Method)
at org.mule.util.queue.QueueInfo.poll(QueueInfo.java:94)
at org.mule.util.queue.TransactionalQueueManager$QueueTransactionContext.poll(TransactionalQueueManager.java:337)
at org.mule.util.queue.TransactionalQueueSession$QueueImpl.poll(TransactionalQueueSession.java:107)
at org.mule.providers.vm.VMMessageReceiver.getMessages(VMMessageReceiver.java:139)
at org.mule.providers.TransactedPollingMessageReceiver$1.doInTransaction(TransactedPollingMessageReceiver.java:120)
at org.mule.transaction.TransactionTemplate.execute(TransactionTemplate.java:92)
at org.mule.providers.TransactedPollingMessageReceiver.poll(TransactedPollingMessageReceiver.java:131)
at org.mule.providers.PollingReceiverWorker.run(PollingReceiverWorker.java:47)
at org.mule.providers.vm.VMMessageReceiver$VMReceiverWorker.run(VMMessageReceiver.java:190)
at org.mule.impl.work.WorkerContext.run(WorkerContext.java:310)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1061)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:575)
at java.lang.Thread.run(Thread.java:534)
[01-16 23:56:38] INFO DefaultExceptionStrategy [vm.receiver.1]: There is no current event available, routing Null message with the exception
[01-16 23:56:38] INFO VMConnector [main]: Disposed: VMConnector{this=ab444, started=false, initialised=false, name='vm', disposed=true, numberOfConcurrentTransactedReceivers=1, createMultipleTransactedReceivers=true, connected=false, supportedProtocols=[vm], serviceOverrides=null}
[01-16 23:56:38] INFO SedaModel [main]: test has been destroyed successfullyShow[01-16 23:52:58] DEBUG Base64Encoder [main]: Object after transform: SUQ9MDQ4YzE4MWUtYzQ3NS0xMWRjLWFmNGYtY2QyOGJhMTljMjUz [01-16 23:52:58] DEBUG Base64Encoder [main]: The transformed object is of expected type. Type is: String [01-16 23:52:58] DEBUG VMConnector [main]: Borrowing a dispatcher for endpoint: vm://in [01-16 23:52:58] DEBUG ObjectToByteArray [main]: java.lang.Object has been added as source type for this transformer, there will be no source type checking performed [01-16 23:52:58] DEBUG VMConnector [main]: Borrowed dispatcher: VMMessageDispatcher{this=7c3885, endpoint=vm://in} [01-16 23:52:58] DEBUG MuleMessage [main]: new copy of message for Thread[main,5,main] [01-16 23:52:58] DEBUG VMConnector [main]: Returning dispatcher for endpoint: vm://in = VMMessageDispatcher{this=7c3885, endpoint=vm://in} [01-16 23:52:58] DEBUG MuleMessage [vm.dispatcher.1]: new copy of message for Thread[vm.dispatcher.1,5,main] [01-16 23:52:58] DEBUG TransportServiceDescriptor [main]: Loading endpointUri resolver: org.mule.impl.endpoint.ResourceNameEndpointBuilder [01-16 23:52:58] DEBUG VMMessageDispatcher [vm.dispatcher.1]: Connecting: VMMessageDispatcher{this=7c3885, endpoint=vm://in} [01-16 23:52:58] DEBUG VMConnector [main]: Borrowing a dispatcher for endpoint: vm://out [01-16 23:52:58] INFO VMMessageDispatcher [vm.dispatcher.1]: Connected: VMMessageDispatcher{this=7c3885, endpoint=vm://in} [01-16 23:52:58] DEBUG ObjectToByteArray [main]: java.lang.Object has been added as source type for this transformer, there will be no source type checking performed [01-16 23:52:58] DEBUG VMConnector [vm.dispatcher.1]: Retrieving new VM queue session from queue manager [01-16 23:52:58] DEBUG VMConnector [main]: Borrowed dispatcher: VMMessageDispatcher{this=3257b8, endpoint=vm://out} [01-16 23:52:58] DEBUG VMMessageDispatcher [main]: Connecting: VMMessageDispatcher{this=3257b8, endpoint=vm://out} [01-16 23:52:58] DEBUG VMMessageDispatcher [vm.dispatcher.1]: dispatched Event on endpointUri: vm://in [01-16 23:52:58] INFO VMMessageDispatcher [main]: Connected: VMMessageDispatcher{this=3257b8, endpoint=vm://out} [01-16 23:52:58] DEBUG VMConnector [main]: Retrieving new VM queue session from queue manager [01-16 23:52:58] DEBUG VMMessageDispatcher [main]: Waiting for a message on out [01-16 23:52:59] DEBUG TransactionTemplate [vm.receiver.1]: Beginning transaction [01-16 23:52:59] DEBUG VMTransaction [vm.receiver.1]: Beginning transaction [01-16 23:52:59] DEBUG TransactionalQueueManager [vm.receiver.1]: Beginning transaction 051b11b2-c475-11dc-af4f-cd28ba19c253[no transaction, readonly] [01-16 23:52:59] DEBUG TransactionalQueueManager [vm.receiver.1]: Began transaction 051b11b2-c475-11dc-af4f-cd28ba19c253[active, readonly] [01-16 23:52:59] DEBUG TransactionCoordination [vm.receiver.1]: Binding new transaction (1) org.mule.providers.vm.VMTransaction@1318b [01-16 23:52:59] DEBUG TransactionTemplate [vm.receiver.1]: Transaction successfully started [01-16 23:52:59] DEBUG VMConnector [vm.receiver.1]: Retrieved VM queue session org.mule.util.queue.TransactionalQueueSession@5bb966 from current transaction org.mule.providers.vm.VMTransaction@1318b [01-16 23:53:08] DEBUG VMMessageDispatcher [main]: No event received after 10000 ms ------------------ [01-16 23:56:28] INFO TransactionalQueueManager [main]: Stopping ResourceManager [01-16 23:56:28] INFO TransactionalQueueManager [main]: Waiting for tx 7c9836b5-c475-11dc-ad34-09ec0a840d00[active] to finish for 10000 milli seconds [01-16 23:56:38] WARN TransactionalQueueManager [main]: Tx 7c9836b5-c475-11dc-ad34-09ec0a840d00[active] failed to finish in given time [01-16 23:56:38] WARN TransactionalQueueManager [main]: Failed to stop ResourceManager [01-16 23:56:38] INFO VMConnector [main]: Removing listener on endpointUri: vm://in [01-16 23:56:38] INFO SedaModel [main]: Component test has been stopped successfully [01-16 23:56:38] INFO VMConnector [main]: Disposing: VMConnector{this=ab444, started=false, initialised=false, name='vm', disposed=false, numberOfConcurrentTransactedReceivers=1, createMultipleTransactedReceivers=true, connected=false, supportedProtocols=[vm], serviceOverrides=null} [01-16 23:56:38] INFO VMConnector [main]: Stopped: VMConnector{this=ab444, started=false, initialised=false, name='vm', disposed=false, numberOfConcurrentTransactedReceivers=1, createMultipleTransactedReceivers=true, connected=false, supportedProtocols=[vm], serviceOverrides=null} [01-16 23:56:38] INFO VMMessageDispatcher [main]: Disconnected: VMMessageDispatcher{this=ff94b1, endpoint=vm://in} [01-16 23:56:38] INFO VMMessageDispatcher [main]: Disconnected: VMMessageDispatcher{this=edf730, endpoint=vm://out} [01-16 23:56:38] INFO TransactionTemplate [vm.receiver.1]: Exception Caught in Transaction template. Handing off to exception handler: org.mule.impl.DefaultExceptionStrategy@ab54eb [01-16 23:56:38] ERROR DefaultExceptionStrategy [vm.receiver.1]: Caught exception in Exception Strategy: null java.lang.InterruptedException at java.lang.Object.wait(Native Method) at org.mule.util.queue.QueueInfo.poll(QueueInfo.java:94) at org.mule.util.queue.TransactionalQueueManager$QueueTransactionContext.poll(TransactionalQueueManager.java:337) at org.mule.util.queue.TransactionalQueueSession$QueueImpl.poll(TransactionalQueueSession.java:107) at org.mule.providers.vm.VMMessageReceiver.getMessages(VMMessageReceiver.java:139) at org.mule.providers.TransactedPollingMessageReceiver$1.doInTransaction(TransactedPollingMessageReceiver.java:120) at org.mule.transaction.TransactionTemplate.execute(TransactionTemplate.java:92) at org.mule.providers.TransactedPollingMessageReceiver.poll(TransactedPollingMessageReceiver.java:131) at org.mule.providers.PollingReceiverWorker.run(PollingReceiverWorker.java:47) at org.mule.providers.vm.VMMessageReceiver$VMReceiverWorker.run(VMMessageReceiver.java:190) at org.mule.impl.work.WorkerContext.run(WorkerContext.java:310) at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1061) at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:575) at java.lang.Thread.run(Thread.java:534) [01-16 23:56:38] INFO DefaultExceptionStrategy [vm.receiver.1]: There is no current event available, routing Null message with the exception [01-16 23:56:38] INFO VMConnector [main]: Disposed: VMConnector{this=ab444, started=false, initialised=false, name='vm', disposed=true, numberOfConcurrentTransactedReceivers=1, createMultipleTransactedReceivers=true, connected=false, supportedProtocols=[vm], serviceOverrides=null} [01-16 23:56:38] INFO SedaModel [main]: test has been destroyed successfully -
Similar Issues:None
Description
see org.mule.providers.vm.functional.VmTransactionTestCase
message was not delivered
Issue Links
- is blocked by
-
MULE-3312
New QueueManager implementation for VMConnector not complete, leading to unusable VM transaction feature
-
Activity
TransactionalQueueManager.QueueTransactionContext.poll(QueueInfo queue, long timeout) doesn't use timeout variable
2.x
http://fisheye.codehaus.org/changelog/mule/?cs=10380
http://fisheye.codehaus.org/changelog/mule/?cs=10383
Current state for 2.x - test is disabled
2.x:
Exception stack is:
1. Resource manager has not been started (org.mule.util.xa.ResourceManagerSystemException)
org.mule.util.xa.AbstractResourceManager:421 (http://mule.mulesource.org/docs/apidocs/org/mule/util/xa/ResourceManagerSystemException.html)
********************************************************************************
Root Exception stack trace:
org.mule.util.xa.ResourceManagerSystemException: Resource manager has not been started
at org.mule.util.xa.AbstractResourceManager.assureStarted(AbstractResourceManager.java:421)
at org.mule.util.xa.AbstractResourceManager.beginTransaction(AbstractResourceManager.java:183)
at org.mule.util.xa.DefaultXASession.begin(DefaultXASession.java:69)
at org.mule.providers.vm.VMTransaction.doBegin(VMTransaction.java:46)
at org.mule.transaction.AbstractTransaction.begin(AbstractTransaction.java:79)
at org.mule.transaction.AbstractSingleResourceTransaction.begin(AbstractSingleResourceTransaction.java:40)
at org.mule.providers.vm.VMTransactionFactory.beginTransaction(VMTransactionFactory.java:24)
at org.mule.transaction.TransactionTemplate.execute(TransactionTemplate.java:86)
at org.mule.providers.TransactedPollingMessageReceiver.poll(TransactedPollingMessageReceiver.java:131)
at org.mule.providers.PollingReceiverWorker.run(PollingReceiverWorker.java:47)
at org.mule.providers.vm.VMMessageReceiver$VMReceiverWorker.run(VMMessageReceiver.java:191)
at org.mule.impl.work.WorkerContext.run(WorkerContext.java:310)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1061)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:575)
at java.lang.Thread.run(Thread.java:534)
We are also seeing this problem while using transacted VM transports in Mule 1.4.3.
Anatoli, what's the status of this issue, Do you have a fix in dev?
Thanks Anatoli, possible to put a patch here? Or the URL for Fisheye for us to build the patch and put here.
2Hassan - fisheye links was publish in the comments
1.x http://fisheye.codehaus.org/changelog/mule/?cs=10366
2L Siraj - Yes, the changes were merged to 2.x. Unfortunately, I got a exception related with Resource manager (see above). As a result the issue is still open
For those interested in the patch - follow the FishEye link, it will allow to generate arbitrary patches from a changeset.
Anatoli,
Which test case do you execute to run into the remaining problem or is it fixed by now?
-Andreas
To spare others reading through this issue here's a quick summary:
#1 org.mule.providers.vm.functional.VmTransactionTestCase is the relevant test case currently disabled
#2 On the latest checkout at this writing, the test fails due to xml parsing issues and not because of Resource manager problems
I'll investigate further and try cleaning up the config first then come back with updates.
Moving into 2.0.2 as it turns out VM transactions are not working due to QueueManager equality issue in VMConnector and VMTransaction. The logic and maybe even the design appears to have changed with 2.x and MuleManager being MuleContext now. In 1.x there was only a QueueManager singletion started in MuleManager. In 2.x we now have a per VMConnector QueueManager. Also, the QueueManager is never started in 2.x but was in MuleManager as part of start() in 1.x. More details later.
Can someone please confirm that in 1.x we only had a single QueueManager across all VMConnectors but with 2.x a per VMConnector QueueManager is intended.
If the above statement is true there are some observations that I believe need to be resolved:
#1 Is MuleContext.getQueueManager() still required or rather obsolete? Please check on DefaultMuleContext.getQueueManager() implementation creating a singleton. If it's in fact still relevant, should at least be started during MuleContext.start()?
#2 The current transaction binding while creating the transport specific transaction VMTransaction uses MuleContext's singleton QueueManager instance to set the QueueManager. This in turn leads to a the situation where the VMConnector.getQueueSession() never properly returns a session because it permanently compares its connector specific QueueManager to the singleton constructed in the beginning.
#3 Based on #1 and #2 my current conclusion on QueueManager is that the design changed and per VMConnector QueueManagers and hence queues are possible. There are just various places that haven't taken this into account as can be seen in the constructor of VMTransaction when creating the initial binding, missing QueueManager start call, or when the thread bound Transaction is returned in VMConnector.getQueueSession() and then failing with 'tx.hasResource(queueManager)'. The overall challenge here appears to be able to properly manage connector bound QueueManagers through MuleContext without having the connector specific QueueManager available when needed, e.g. in TransactionTemplate.execute() when the transaction gets started with "config.getFactory().beginTransaction(context).
I hope someone can shed some more light into these changes for 2.x as they seem to be somewhat inconsistent.
Oh, and coming back to the test failures, yes, that's why they are failing at this point:
#1 QueueManager not started
#2 QueueManager in connector never matches previously configured VMTransaction QueueManager
Thanks in advance,
-Andreas
Came across the answer for QueueManager per connector in the linked issue.
Based on my findings I created a new issue on the actual problem MULE-3312.
The original issue is fixed, still the tests are failing. I will create a new issue because the reason for failure has moved to a different place in the core.
People
Dates
-
- Created:
- Updated:
- Resolved:
possible reason is
MULE-2396MULE-2396