[MULE 2] Work caused exception on 'workCompleted'

[Enrique Rodríguez]

Hi, I need help from a Mule core developer to overcome this problem.
I'm using Mule 2.0.2 on Linux, and after a few days it starts logging this error:

Work caused exception on 'workCompleted'. Work being executed was: org.mule.transport.AbstractMessageDispatcher$Worker@1abe3a

It happens on org.mule.transport.vm.VMConnector logger, and after a bit of research, I found it really happens on class
org.mule.transport.AbstractConnector, method handleWorkException(WorkEvent, String), in line 1746, in which the error is logged.

It seems that the event has an exception (event.getException != null). Oddly, the exception never gets logged, just this messge.

After this scenario is set, all VMConnectors, one by one, starts refusing requests. If I restats Mule, it works fine for a few days or so.
In addition, the thread executing the method is named vmQueue.dispatcher.1502. Looks like Mule starts creating threads. Before this scenario, I have 10 vmQueue.dispatcher threads.

Despite the name, I'm not using queued vm connector.

I saw that others has this problem too, but didn't saw solutions. Has anyone solved it, o work-around it?

Thanks in advance,
Q.-

My vmConnector config:

<vm:connector name="vmQueue" queueEvents="false">
    <receiver-threading-profile doThreading="true"
                                         maxThreadsActive= "250"
                                         maxThreadsIdle= "250"
                                         poolExhaustedAction="WAIT"
                                         maxBufferSize="100"
                                         threadWaitTimeout="240000"/>
    <dispatcher-threading-profile doThreading="true"
                                         maxThreadsActive= "10"
                                         maxThreadsIdle= "10"
                                         poolExhaustedAction="WAIT"
                                         maxBufferSize="100"
                                         threadWaitTimeout="240000"/>
    <vm:queueProfile maxOutstandingMessages="100"/>
</vm:connector>



class AbstractConnector:

    protected void handleWorkException(WorkEvent event, String type)
    {
        if (event == null)
        {
            return;
        }

        Throwable e = event.getException();

        if (e == null)
        {
            return;
        }

        if (e.getCause() != null)
        {
            e = e.getCause();
        }

        logger.error("Work caused exception on '" + type + "'. Work being executed was: "
                        + event.getWork().toString());

        if (e instanceof Exception)
        {
            this.handleException((Exception) e);
        }
        else
        {
            throw new MuleRuntimeException(CoreMessages.connectorCausedError(this.getName()), e);
        }
    }

[antoine.borg]

Hi,

 

Can you post your configuration and the log file pls? It's hard to say what your problem is without those.

 

Cheers

A

 

Antoine Borg, Senior Consultant | Tel: [phone] 
ricston Ltd., BP 2, 1180 Uccle, Brussels, BELGIUM

email: antoine.borgantoine.borg@... | blog: blog.ricston.com | web: ricston.com 

 

---

From: Enrique Rodríguez [mailto:enrique.rodriguez@...]
Sent: Thursday, November 20, 2008 6:29 PM
To: user@...
Subject: [mule-user] [MULE 2] Work caused exception on 'workCompleted'

Hi, I need help from a Mule core developer to overcome this problem. I'm using Mule 2.0.2 on Linux, and after a few days it starts logging this error: Work caused exception on 'workCompleted'. Work being executed was: org.mule.transport.AbstractMessageDispatcher$Worker@1abe3a It happens on org.mule.transport.vm.VMConnector logger, and after a bit of research, I found it really happens on class org.mule.transport.AbstractConnector, method handleWorkException(WorkEvent, String), in line 1746, in which the error is logged. It seems that the event has an exception (event.getException != null). Oddly, the exception never gets logged, just this messge. After this scenario is set, all VMConnectors, one by one, starts refusing requests. If I restats Mule, it works fine for a few days or so. In addition, the thread executing the method is named vmQueue.dispatcher.1502. Looks like Mule starts creating threads. Before this scenario, I have vmQueue.dispatcher threads. Despite the name, I'm not using queued vm connector. I saw that others has this problem too, but didn't saw solutions. Has anyone solved it, o work-around it? Thanks in advance, Q.- My vmConnector config: class AbstractConnector: protected void handleWorkException(WorkEvent event, String type) { if (event == null) { return; } Throwable e = event.getException(); if (e == null) { return; } if (e.getCause() != null) { e = e.getCause(); } logger.error("Work caused exception on '" + type + "'. Work being executed was: " + event.getWork().toString()); if (e instanceof Exception) { this.handleException((Exception) e); } else { throw new MuleRuntimeException(CoreMessages.connectorCausedError(this.getName()), e); } }

---

View this message in context: [MULE 2] Work caused exception on 'workCompleted'
Sent from the Mule - User mailing list archive at Nabble.com.

[Enrique Rodríguez]

Hi, here goes a sample config. Hope this helps.

    <!-- mule-config.xml -->
    <tcp:connector name="TcpConnector">
        <receiver-threading-profile doThreading="true"
                                             maxThreadsActive="150"
                                             maxThreadsIdle="50"
                                             poolExhaustedAction="WAIT"
                                             maxBufferSize="100"
                                             threadWaitTimeout="240000"/>
    </tcp:connector>

    <vm:connector name="vmQueue" queueEvents="false">
        <receiver-threading-profile doThreading="true"
                                             maxThreadsActive= "250"
                                             maxThreadsIdle= "250"
                                             poolExhaustedAction="WAIT"
                                             maxBufferSize="100"
                                             threadWaitTimeout="240000"/>
        <dispatcher-threading-profile doThreading="true"
                                                maxThreadsActive= "10"
                                                maxThreadsIdle= "10"
                                                poolExhaustedAction="WAIT"
                                                maxBufferSize="100"
                                                threadWaitTimeout="240000"/>
        <vm:queueProfile maxOutstandingMessages="100"/>
    </vm:connector>
   
    <model name="ServiceBrokerModel">
        <service name="ServiceBroker">
            <inbound>
                <tcp:inbound-endpoint address="tcp://localhost:6853"
                                                remoteSync="true"
                                                transformer-refs="ByteArrayToSerializable"
                                                connector-ref="TcpConnector"/>
                <inbound-endpoint ref="serviceBroker" remoteSync="true"/>
            </inbound>
            <component>
                <!--
                -- This component dispatches messages to a service based on some
                -- properties of the message.
                -->
                <spring-object bean="DispatcherComponent"/>
            </component>
            <outbound>
                <forwarding-catch-all-strategy>
                    <vm:outbound-endpoint ref="serviceBrokerResponse"/>
                </forwarding-catch-all-strategy>
                <static-recipient-list-router>
                    <reply-to address="vm://serviceBrokerResponse"/>
                    <payload-type-filter expectedType="com.abitab.servicebroker.Request"/>
                </static-recipient-list-router>
            </outbound>

            <async-reply timeout="25000">
                <vm:inbound-endpoint path="serviceBrokerResponse"
                                               connector-ref="vmQueue"
                                               transformer-refs="ObjectToResponse"/>
                <single-async-reply-router/>
            </async-reply>
        </service>
    </model>


   
    <!-- SomeService-mule-config.xml -->
    <model name="SomeServiceModel">
        <service name="SomeService_operation">
            <inbound>
                <vm:inbound-endpoint path="SomeService_operation" />
            </inbound>
            <outbound>
                <custom-outbound-router
                                        class="com.abitab.servicebroker.mule.routers.RetryOutboundRouter">
                    <axis:outbound-endpoint address="<...url...>"
                                                      remoteSync="true"
                                                      style="RPC"
                                                      use="ENCODED">
                        <axis:soap-method method="<...method...>">
                            <...axis config...>
                        </axis:soap-method>
                        <transformers>
                            <...transformers...>
                        </transformers>
                        <response-transformers>
                            <...transformers...>
                        </response-transformers>
                    </axis:outbound-endpoint>
                </custom-outbound-router>
            </outbound>
        </service>
    </model>



    // DispatcherComponent.java

    public Object onCall(MuleEventContext eventContext) {
        Request request = (Request)eventContext.transformMessage();

        List recipients = new ArrayList();

        recipients.add("vm://" + request.getServiceId() + "_" + request.getOperationId());

        eventContext.getMessage().setProperty("recipients", recipients);

        return request;
    }

[Enrique Rodríguez]

In the log, there is only entries like:

<log4j:event logger="org.mule.transport.vm.VMConnector"
                  timestamp="1227190581807"
                  level="ERROR"
                  thread="vmQueue.dispatcher.4">
<log4j:message>
    <![CDATA[Work caused exception on 'workCompleted'. Work being executed was: org.mule.transport.AbstractMessageDispatcher$Worker@1bf836]]>
    </log4j:message>
</log4j:event>

There is not stacktrace dump nor anything else. Just a lot of entries like this one.

[Enrique Rodríguez]

After a lot of testing, a light is in the end of the tunnel....

It seems to be a memory problem. Right now, I'm testing with a bigger heap.

Stay tunned...

[mahanare]

Even we used to get this exception frequently, but after certain other changes, in recent times we didnt see this exception at all.

Enrique Rodríguez wrote:

After a lot of testing, a light is in the end of the tunnel....

It seems to be a memory problem. Right now, I'm testing with a bigger heap.

Stay tunned...

[Enrique Rodríguez]

Hi mahanare.

In mule 2.0.0 this problem happens more often than in 2.0.2.

What kind of changes are you talking about? Changes in your application/configuration? Or in the platform (Mule, JDK, etc)?

[mahanare]

It was just with configuration. we have done some design changes in our application (mostly in the configuration).
Not sure what fixed it exactly.

Enrique Rodríguez wrote:

Hi mahanare.

In mule 2.0.0 this problem happens more often than in 2.0.2.

What kind of changes are you talking about? Changes in your application/configuration? Or in the platform (Mule, JDK, etc)?

[Daniel Feist]

Please try with 2.1.1 and if it still fails post config file and full  
stacktrace.

thanks,

On Nov 28, 2008, at 1:49 PM, Enrique Rodríguez wrote:

>
> Hi mahanare.
>
> In mule 2.0.0 this problem happens more often than in 2.0.2.
>
> What kind of changes are you talking about? Changes in your
> application/configuration? Or in the platform (Mule, JDK, etc)?
>
> --
> View this message in context: http://www.nabble.com/-MULE-2--Work-caused-exception-on-%27workCompleted%27-tp20606236p20736683.html
> Sent from the Mule - User mailing list archive at Nabble.com.
>
>
> ---------------------------------------------------------------------
> To unsubscribe from this list, please visit:
>
>    http://xircles.codehaus.org/manage_email
>
>

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email

[Enrique Rodríguez]

Hi Daniel, I'll try 2.1.1 and let you know.

BTW, I just constrained the heap of the JMV to 32m and after about 2500 messages I got

org.mule.transport.tcp.TcpConnector: Work caused exception on 'workCompleted'. Work being executed was: org.mule.transport.tcp.TcpMessageReceiver$TcpWorker@bdd2cf

and

Exception in thread "RMI TCP Connection(idle)" java.lang.OutOfMemoryError: Java heap space

printed to the stderr.

Those messages where sent by 3 procesess with 10 threads each process, and each threads sent 100 messages.