Issue Details (XML | Word | Printable)

Key: MULE-2905
Type: Bug Bug
Status: Closed Closed
Resolution: Fixed
Priority: Major Major
Assignee: Andreas Guenther
Reporter: Anatoli Kuzmin
Votes: 1
Watchers: 1
Operations

If you were logged in you would be able to see more operations.
Mule

VM hangs on with transaction

Created: 16/Jan/08 02:58 PM   Updated: 09/May/08 03:28 PM
Component/s: Transport: VM
Affects Version/s: 1.4.4, 2.0.0-RC2
Fix Version/s: 2.0.2

Time Tracking:
Not Specified

Issue Links:
Block
 
Related

Labels:
User impact: High
Configuration:
<?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:
[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


 Description  « Hide
see org.mule.providers.vm.functional.VmTransactionTestCase
message was not delivered

 All   Comments   Work Log   Change History   Transitions   FishEye      Sort Order: Ascending order - Click to sort in descending order
Anatoli Kuzmin added a comment - 17/Jan/08 08:51 AM
possible reason is MULE-2396

Anatoli Kuzmin added a comment - 17/Jan/08 09:12 AM
TransactionalQueueManager.QueueTransactionContext.poll(QueueInfo queue, long timeout) doesn't use timeout variable


Anatoli Kuzmin added a comment - 17/Jan/08 09:57 AM

Anatoli Kuzmin added a comment - 18/Jan/08 04:37 AM

Anatoli Kuzmin added a comment - 18/Jan/08 04:38 AM
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)

Hassan Sajjad added a comment - 10/Apr/08 04:05 AM

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?


Anatoli Kuzmin added a comment - 10/Apr/08 04:13 AM
This issue was fixed.
Could you please try 1.4.4 snapshot?

Hassan Sajjad added a comment - 10/Apr/08 06:17 AM
Thanks Anatoli, possible to put a patch here? Or the URL for Fisheye for us to build the patch and put here.

L Siraj added a comment - 10/Apr/08 06:25 AM
Hi,

Looking at the Mule 2.0.0 code, it seems as though it has been patched: Lines 337 and 315 i think. However since this jira is still open can we assume that the issue is still there even with these changes in place?

L


Anatoli Kuzmin added a comment - 10/Apr/08 07:22 AM
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


Andrew Perepelytsya added a comment - 10/Apr/08 07:29 AM
For those interested in the patch - follow the FishEye link, it will allow to generate arbitrary patches from a changeset.

L Siraj added a comment - 10/Apr/08 09:40 AM
Hi Andrew, Would you be able to explain further?

Andreas Guenther added a comment - 23/Apr/08 12:02 PM
Anatoli,

Which test case do you execute to run into the remaining problem or is it fixed by now?

-Andreas


Anatoli Kuzmin added a comment - 24/Apr/08 03:28 AM
see test cases description and prev comments

Andreas Guenther added a comment - 24/Apr/08 12:52 PM
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.


Anatoli Kuzmin added a comment - 24/Apr/08 01:26 PM

1.4.4: this issue was fixed
2.x:Resource manager problem


Andreas Guenther added a comment - 02/May/08 10:35 PM
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.

Andreas Guenther added a comment - 06/May/08 07:31 PM
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


Andreas Guenther added a comment - 06/May/08 09:30 PM
Came across the answer for QueueManager per connector in the linked issue.

Andreas Guenther added a comment - 06/May/08 09:38 PM
Based on my findings I created a new issue on the actual problem MULE-3312.

Andreas Guenther added a comment - 08/May/08 08:24 PM
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.