Issue Details (XML | Word | Printable)

Key: MULE-1564
Type: Bug Bug
Status: Reopened Reopened
Priority: Major Major
Assignee: Unassigned
Reporter: Travis Carlson
Votes: 0
Watchers: 1
Operations

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

VMLoanBrokerSynchronousFunctionalTestCase logs a warning regarding a null MULE_REMOTE_SYNC property

Created: 07/Apr/07 03:24 PM   Updated: 06/May/08 02:09 AM
Component/s: Examples / Tutorials
Affects Version/s: 1.4.0
Fix Version/s: None

Time Tracking:
Not Specified

Issue Links:
Block
Related
 

Labels:
User impact: Medium
Log Output:
[04-07 17:19:40] WARN DefaultMessageAdapter [connector.VM.0.dispatcher.3]: setProperty(key, value) called with null value; removing key: MULE_REMOTE_SYNC; please report the following stack trace to dev@mule.codehaus.org.
java.lang.Throwable
        at org.mule.providers.AbstractMessageAdapter.setProperty(AbstractMessageAdapter.java:142)
        at org.mule.providers.DefaultMessageAdapter.<init>(DefaultMessageAdapter.java:89)
        at org.mule.impl.MuleMessage.<init>(MuleMessage.java:69)
        at org.mule.providers.vm.VMMessageReceiver.onEvent(VMMessageReceiver.java:96)
        at org.mule.providers.vm.VMMessageDispatcher.doDispatch(VMMessageDispatcher.java:157)
        at org.mule.providers.AbstractMessageDispatcher$Worker.run(AbstractMessageDispatcher.java:561)
        at org.mule.impl.work.WorkerContext.run(WorkerContext.java:310)
        at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:987)
        at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:528)
        at java.lang.Thread.run(Thread.java:534)


 Description  « Hide
org.mule.examples.loanbroker.esn.VMLoanBrokerSynchronousFunctionalTestCase is logging an ugly warning regarding a null MULE_REMOTE_SYNC property

 All   Comments   Work Log   Change History   Transitions   FishEye      Sort Order: Ascending order - Click to sort in descending order
Andrew Cooke added a comment - 09/Apr/07 01:24 PM
This isn't just a warning - he test is failing (well, the test is passing, but it's not actually doing anything).

I'm looking at this because I need this test to work for MULE-1551.


Andrew Cooke added a comment - 09/Apr/07 01:55 PM
Just to correct the above - I think the test is working after all. Sorry.

Andrew Cooke added a comment - 10/Apr/07 04:49 PM
This is a multithreading issue.

The problem occurs when a MuleMessage contains properties named "method" or "MULE_REMOTE_SYNC". These properties are being deleted in MuleSession.processResponse. However, at the same time, within AbstractMessageDispatcher, another thread is making a copy of the message properties. This second thread requests an iterator over names which is then uses to access the properties. The affected property names appear in the iterator list, but they are deleted from the message before read for copying. As a consequence null values are found.

I can imagine various hacks to solve this, but the underlying problem is a lack of sequencing in the message handling. So I am assigning this to Holger.


Andrew Cooke added a comment - 10/Apr/07 04:52 PM
Correction: the error occurs in AbstractMesssageAdapter (not Dispatcher) and occurs within MuleMessage constructor (line 74) when copying properties from a previous message. This is itself occurring in VmMessageReceiver (line 96).

Andrew Perepelytsya added a comment - 23/Jun/07 11:42 PM
Branch https://svn.codehaus.org/mule/branches/trunk-fix-for-MULE-1564 contains modified core classes which produce a detailed multi-threaded report for the issue at runtime.

Andrew Cooke added a comment - 02/Jul/07 01:51 PM
I believe the following may be related:

================================================================================
= Testing: lots of loan requests =
= (org.mule.examples.loanbroker.esn.XFireLoanBrokerAsynchronousFunctionalTestC =
= ase) =
================================================================================
[07-02 16:49:04] WARN DefaultMessageAdapter [syncVm.dispatcher.5]: setProperty(key, value) called with null value; removing key: method; please report the following stack trace to null
java.lang.Throwable
at org.mule.providers.AbstractMessageAdapter.setProperty(AbstractMessageAdapter.java:141)
at org.mule.providers.DefaultMessageAdapter.<init>(DefaultMessageAdapter.java:88)
at org.mule.impl.MuleMessage.<init>(MuleMessage.java:68)
at org.mule.providers.vm.VMMessageReceiver.onEvent(VMMessageReceiver.java:102)
at org.mule.providers.vm.VMMessageDispatcher.doDispatch(VMMessageDispatcher.java:151)
at org.mule.providers.AbstractMessageDispatcher$Worker.run(AbstractMessageDispatcher.java:608)
at org.mule.impl.work.WorkerContext.run(WorkerContext.java:310)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:987)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:528)
at java.lang.Thread.run(Thread.java:534)

(ignore "please report ... null" - I think that's just because I don't have a manifest as I am not running from a packaged distro).

Line 88 of DefaultMessageAdapter is constructing a new message from the contents of an old one.

I was looking at this test because generally it works fine, but it is one of the tests that fails regularly on CI. I think this is fairly strong confirmation that the CI problems we are seeing are related to this issue.


Andrew Cooke added a comment - 02/Jul/07 02:01 PM
Just trying a local fix. Not intending to cure the greater problem, but perhaps ameliorate the issue a little (and get CI working).

Andrew Cooke added a comment - 02/Jul/07 03:25 PM
I've modified DefaultMessageAdapter to print a warning rather than die when these problems occur.

This doesn't fix the underlying issue, since we still have inpredictable code. And we can have unpredictable code even when there are no messages printed (it's unpredictabe all the time). So I'm not sure how much this will help. But at the moment CI is failing more than it is passing. So it is interesting to see how this changes things.


Andrew Cooke added a comment - 02/Jul/07 03:26 PM
Back to you.

Andrew Cooke added a comment - 02/Jul/07 03:39 PM
output after update - test still fails.

[07-02 20:34:03] WARN DefaultMessageAdapter [syncVm.dispatcher.8]: Detected concurrent access to property method for org.mule.providers.DefaultMessageAdapter{id=92078f5f-28db-11dc-a302-bfddaeaa75bc, payload=org.mule.examples.loanbroker.messages.LoanBrokerQuoteRequest, correlationId=92078f5f-28db-11dc-a302-bfddaeaa75bc, correlationGroup=-1, correlationSeq=-1, encoding=UTF-8, exceptionPayload=null, properties={ MULE_ENDPOINT=vm://lender.service?method=setLenderList MULE_SESSION=SUQ9OTIwODJiYTItMjhkYi0xMWRjLWEzMDItYmZkZGFlYWE3NWJjO0lEPTkyMDgyYmEyLTI4ZGItMTFkYy1hMzAyLWJmZGRhZWFhNzViYw== MULE_ORIGINATING_ENDPOINT=CustomerRequests MULE_CORRELATION_ID=92078f5f-28db-11dc-a302-bfddaeaa75bc }}


Andrew Cooke added a comment - 02/Jul/07 03:43 PM
Going to remove loanbroker tests from CI.

Andrew Cooke added a comment - 09/Jul/07 08:56 AM
I think I "fixed" the synchronous loanbroker tests - the config was missing the synchronous default. With that, and the disabled threading that was already present, these tests now pass. We still have the larger issue of scribbling on asynchronous VM (at least) messaging, but that's amply covered in other issues, so tentatively closing this (have e-enabled tests),

Andrew Perepelytsya added a comment - 09/Jul/07 09:08 AM
The change has to applied to Mule 1.x as well, I don't know why you committed everything to 2.x

Andrew Cooke added a comment - 09/Jul/07 09:26 AM
I didn't realise this was an issue in 1.4.

My fixes are 2.0 specific. They cannot be applied to 1.4. Indeed, all they do (as far as I know) is make the 2.0 code behave as the 1.4 code should.

So there is no code to apply to 1.4. I guess this issue remains open for that version.


Andrew Cooke added a comment - 09/Jul/07 09:28 AM
This seems to be a 1.4 issue, so shifting assignment from me back into the pool.

Andrew Perepelytsya added a comment - 09/Jul/07 09:29 AM
Well, the Affects Version is 1.4, so you have no excuse

Andrew Cooke added a comment - 09/Jul/07 09:36 AM
Yeah, I did wonder whether that was a mistake, but I guess not.

Andrew Cooke added a comment - 12/Jul/07 08:54 AM
This also seen with AxisConnectorJmsTopicsFunctionalTestCase

Andrew Cooke added a comment - 12/Jul/07 08:56 AM
Also, there are two similar but separate issues here. One is attachment handling (DefaultMessageAdapter constructor). The other is properties handling (AbstractMessageAdapter addProperties).