I've relocated ActiveMQ onto the same server as Mule and the problem
repeated itself within 20 minutes of startup. I'm very much starting
to suspect stability issues with my deployments of Mule and/or
ActiveMQ. Check this out;
8:26 - Server startup and all normal operation with new file arriving,
picked up by file connector and handed to FileParser which dispatches a
UMOMessage for each of the 500 or so lines;
INFOÂ 2008-01-09 08:32:52,015 [FileParser.2]
com.metoceanengineers.datafeeds.ingest.components.RecordProcessorUmo:
Dispatched record for "Metocean Office" 08/01/2008 16:00:00.000 GMT
INFOÂ 2008-01-09 08:32:52,259 [FileParser.2]
com.metoceanengineers.datafeeds.ingest.components.RecordProcessorUmo:
Dispatched record for "Metocean Office" 08/01/2008 16:01:00.000 GMT
INFOÂ 2008-01-09 08:32:52,292 [FileParser.2]
com.metoceanengineers.datafeeds.ingest.components.RecordProcessorUmo:
Dispatched record for "Metocean Office" 08/01/2008 16:02:00.000 GMT
...
System now functioning as normal with files arriving every 10 minutes
or so. Of subsequent files, only the last few dispatched records from
FileParser component actually make it onto the JMS connector courtesy
of a stateful AggregatedFileHistoryFilter which does an "if new" test.
8:52 - First sign of trouble. Records being dispatched after
file ingest as normal but then java.io.InterruptedIOException,
javax.jms.JMSException and
edu.emory.mathcs.backport.java.util.concurrent.RejectedExecutionException.Â
Remember ActiveMQ is on the same server as Mule here connecting through
localhost:61616 so I can't see how connectivity is the issue anymore.Â
Restarting Mule re-enables the JMS connection and we're good to go
until the next time it falls over.
...
INFOÂ 2008-01-09 08:52:42,827 [FileParser.7]
com.metoceanengineers.datafeeds.ingest.components.RecordProcessorUmo:
Dispatched record for "ONS_00155" 08/01/2008 00:44:00.000 GMT
INFOÂ 2008-01-09 08:52:42,890 [FileParser.7]
com.metoceanengineers.datafeeds.ingest.components.RecordProcessorUmo:
Dispatched record for "ONS_00155" 08/01/2008 00:45:00.000 GMT
INFOÂ 2008-01-09 08:52:42,942 [FileParser.7]
com.metoceanengineers.datafeeds.ingest.components.RecordProcessorUmo:
Dispatched record for "ONS_00155" 08/01/2008 00:46:00.000 GMT
(all ok but then)
INFOÂ 2008-01-09 08:52:42,956 [FileParser.8]
org.mule.providers.jms.JmsMessageDispatcher: Disconnected:
JmsMessageDispatcher{this=1fc9a67, endpoint=jms://datafeeds.records}
ERROR 2008-01-09 08:52:42,958 [DatafeedFilePublish.dispatcher.1]
org.mule.providers.jms.JmsConnector: Failed to close jms message
producer
javax.jms.JMSException: java.io.InterruptedIOException
       at
org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:58)
       at
org.apache.activemq.ActiveMQConnection.asyncSendPacket(ActiveMQConnection.java:1157)
       at
org.apache.activemq.ActiveMQSession.asyncSendPacket(ActiveMQSession.java:1651)
       at
org.apache.activemq.ActiveMQMessageProducer.close(ActiveMQMessageProducer.java:315)
       at
org.mule.providers.jms.JmsConnector.close(JmsConnector.java:939)
       at
org.mule.providers.jms.JmsConnector.closeQuietly(JmsConnector.java:953)
       at
org.mule.providers.jms.JmsMessageDispatcher.dispatchMessage(JmsMessageDispatcher.java:301)
       at
org.mule.providers.jms.JmsMessageDispatcher.doDispatch(JmsMessageDispatcher.java:64)
       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$Worker.runTask(ThreadPoolExecutor.java:650)
       at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
       at java.lang.Thread.run(Thread.java:595)
Caused by: java.io.InterruptedIOException
       at
org.apache.activemq.transport.WireFormatNegotiator.oneway(WireFormatNegotiator.java:91)
       at
org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:47)
       at
org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60)
       at
org.apache.activemq.ActiveMQConnection.asyncSendPacket(ActiveMQConnection.java:1155)
       ... 11 more
ERROR 2008-01-09 08:52:42,959 [DatafeedFilePublish.dispatcher.1]
org.mule.providers.jms.JmsConnector: Failed to close jms session
consumer
javax.jms.JMSException: java.io.InterruptedIOException
       at
org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:58)
       at
org.apache.activemq.ActiveMQConnection.asyncSendPacket(ActiveMQConnection.java:1157)
       at
org.apache.activemq.ActiveMQSession.close(ActiveMQSession.java:517)
       at
org.mule.providers.jms.JmsConnector.close(JmsConnector.java:1003)
       at
org.mule.providers.jms.JmsConnector.closeQuietly(JmsConnector.java:1017)
       at
org.mule.providers.jms.JmsMessageDispatcher.dispatchMessage(JmsMessageDispatcher.java:323)
       at
org.mule.providers.jms.JmsMessageDispatcher.doDispatch(JmsMessageDispatcher.java:64)
       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$Worker.runTask(ThreadPoolExecutor.java:650)
       at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
       at java.lang.Thread.run(Thread.java:595)
Caused by: java.io.InterruptedIOException
       at
org.apache.activemq.transport.WireFormatNegotiator.oneway(WireFormatNegotiator.java:91)
       at
org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:47)
       at
org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60)
       at
org.apache.activemq.ActiveMQConnection.asyncSendPacket(ActiveMQConnection.java:1155)
       ... 10 more
ERROR 2008-01-09 08:52:42,960 [DatafeedFilePublish.dispatcher.1]
org.mule.impl.DefaultExceptionStrategy: Caught exception in Exception
Strategy: Interrupted.
javax.jms.JMSException: Interrupted.
       at
org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:58)
       at
org.apache.activemq.ActiveMQConnection.syncSendPacket(ActiveMQConnection.java:1185)
       at
org.apache.activemq.ActiveMQSession.send(ActiveMQSession.java:1551)
       at
org.apache.activemq.ActiveMQMessageProducer.send(ActiveMQMessageProducer.java:465)
       at
org.apache.activemq.ActiveMQMessageProducer.send(ActiveMQMessageProducer.java:384)
       at
org.mule.providers.jms.Jms11Support.send(Jms11Support.java:226)
       at
org.mule.providers.jms.JmsMessageDispatcher.dispatchMessage(JmsMessageDispatcher.java:273)
       at
org.mule.providers.jms.JmsMessageDispatcher.doDispatch(JmsMessageDispatcher.java:64)
       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$Worker.runTask(ThreadPoolExecutor.java:650)
       at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
       at java.lang.Thread.run(Thread.java:595)
Caused by: java.io.InterruptedIOException: Interrupted.
       at
org.apache.activemq.transport.FutureResponse.getResult(FutureResponse.java:49)
       at
org.apache.activemq.transport.ResponseCorrelator.request(ResponseCorrelator.java:75)
       at
org.apache.activemq.ActiveMQConnection.syncSendPacket(ActiveMQConnection.java:1175)
       ... 11 more
ERROR 2008-01-09 08:52:42,966 [FileParser.8]
com.metoceanengineers.datafeeds.ingest.components.RecordProcessorUmo:
There has been an error: org.mule.umo.routing.RoutingException: Failed
to route event via endpoint: null. Message payload is of type: String
ERROR 2008-01-09 08:52:42,970 [FileParser.8]
org.mule.impl.DefaultComponentExceptionStrategy:
********************************************************************************
Message              : Failed to route event via endpoint:
MuleEndpoint{endpointUri=jms://datafeeds.records,
connector=JmsConnector{this=6c1a82, started=true, initialised=true,
name='DatafeedFilePublish', disposed=false,
numberOfConcurrentTransactedReceivers=4,
createMultipleTransactedReceivers=true, connected=true,
supportedProtocols=[jms], serviceOverrides=null},
transformer=ObjectToJMSMessage{this=c8ec7e, name='ObjectToJMSMessage',
ignoreBadInput=false, returnClass=null, sourceTypes=[]},
name='endpoint.jms.datafeeds.records', type='senderAndReceiver',
properties={}, transactionConfig=Transaction{factory=null, action=NONE,
timeout=30000}, filter=null, deleteUnacceptedMessages=false,
initialised=true, securityFilter=null, synchronous=null,
initialState=started, createConnector=0, remoteSync=false,
remoteSyncTimeout=10000, endpointEncoding=null}. Message payload is of
type: String
<netcdf
xmlns=
"http://www.unidata.ucar.edu/namespaces/netcdf/ncml-2.2"><dimension
isUnlimited="true" length="1" name="records"/><dimension
length="2" name="timedim"/><attribute name="Conventions"
type="string" value="WNIOM/v2"/><attribute name="data_origin"
type="string" value="measured"/><attribute name="project"
type="string" value="A0468 Internal Datafeeds"/><attribute
name="history" type="string" value="Mule ingest to NetCDF
store"/><attribute name="client" type="string" value="RPS
Metocean"/><attribute name="location" type="string"
value="ONS_00155"/><attribute name="DataFeedId" type="string"
value="ONS_00155"/><attribute name="logging_system" type="string"
value="UTC"/><variable name="Time" shape="records timedim"
type="int"><values>20080108
57660000</values></variable><variable name="WS"
shape="records"
type="float"><values>5.8</values><attribute
name="units" type="string"
value="m/s"/></variable><variable name="WD" shape="records"
type="float"><values>228.0</values><attribute
name="units" type="string"
value="deg"/></variable><variable name="WG" shape="records"
type="float"><values>7.5</values><attribute
name="units" type="string"
value="m/s"/></variable><variable name="ST" shape="records"
type="float"><values>8.0</values><attribute
name="units" type="string"
value="deg"/></variable><variable name="AT" shape="records"
type="float"><values>28.1</values><attribute
name="units" type="string"
value="degC"/></variable><variable name="RH"
shape="records"
type="float"><values>75.5</values><attribute
name="units" type="string" value="%"/></variable><variable
name="BP" shape="records"
type="float"><values>1008.2</values><attribute
name="units" type="string"
value="hPa"/></variable><variable name="BV" shape="records"
type="float"><values>12.71</values><attribute
name="units" type="string" value="V"/></variable><variable
name="VWS" shape="records"
type="float"><values>5.8</values><attribute
name="units" type="string"
value="m/s"/></variable><variable name="VWD"
shape="records"
type="float"><values>228.0</values><attribute
name="units" type="string"
value="deg"/></variable></netcdf>
********************************************************************************
Exception stack is:
1. null
(edu.emory.mathcs.backport.java.util.concurrent.RejectedExecutionException)
 org.mule.util.concurrent.WaitPolicy:56 (null)
2. Failed to route event via endpoint:
MuleEndpoint{endpointUri=jms://datafeeds.records,
connector=JmsConnector{this=6c1a82, started=true, initialised=true,
name='DatafeedFilePublish', disposed=false,
numberOfConcurrentTransactedReceivers=4,
createMultipleTransactedReceivers=true, connected=true,
supportedProtocols=[jms], serviceOverrides=null},
transformer=ObjectToJMSMessage{this=c8ec7e, name='ObjectToJMSMessage',
ignoreBadInput=false, returnClass=null, sourceTypes=[]},
name='endpoint.jms.datafeeds.records', type='senderAndReceiver',
properties={}, transactionConfig=Transaction{factory=null, action=NONE,
timeout=30000}, filter=null, deleteUnacceptedMessages=false,
initialised=true, securityFilter=null, synchronous=null,
initialState=started, createConnector=0, remoteSync=false,
remoteSyncTimeout=10000, endpointEncoding=null}. Message payload is of
type: String (org.mule.umo.provider.DispatchException)
edu.emory.mathcs.backport.java.util.concurrent.RejectedExecutionException
       at
org.mule.util.concurrent.WaitPolicy.rejectedExecution(WaitPolicy.java:56)
       at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:391)
       at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:865)
       at
org.mule.impl.work.ScheduleWorkExecutor.doExecute(ScheduleWorkExecutor.java:39)
       at
org.mule.impl.work.MuleWorkManager.executeWork(MuleWorkManager.java:276)
       at
org.mule.impl.work.MuleWorkManager.scheduleWork(MuleWorkManager.java:243)
       at
org.mule.providers.AbstractMessageDispatcher.dispatch(AbstractMessageDispatcher.java:149)
       at
org.mule.providers.AbstractConnector.dispatch(AbstractConnector.java:1583)
       at
org.mule.impl.ImmutableMuleEndpoint.dispatch(ImmutableMuleEndpoint.java:929)
       at org.mule.impl.MuleSession.dispatchEvent(MuleSession.java:259)
       at org.mule.impl.MuleSession.dispatchEvent(MuleSession.java:162)
       at
org.mule.routing.outbound.AbstractOutboundRouter.dispatch(AbstractOutboundRouter.java:81)
       at
org.mule.routing.outbound.FilteringOutboundRouter.route(FilteringOutboundRouter.java:70)
       at
org.mule.routing.outbound.OutboundRouterCollection$1.doInTransaction(OutboundRouterCollection.java:66)
       at
org.mule.transaction.TransactionTemplate.execute(TransactionTemplate.java:39)
       at
org.mule.routing.outbound.OutboundRouterCollection.route(OutboundRouterCollection.java:71)
       at org.mule.impl.MuleSession.dispatchEvent(MuleSession.java:139)
       at
org.mule.impl.MuleEventContext.dispatchEvent(MuleEventContext.java:478)
       at
com.metoceanengineers.datafeeds.ingest.components.AbstractRecordProcessorUmo.processIngest(AbstractRecordProcessorUmo.java:117)
       at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
       at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
       at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
       at java.lang.reflect.Method.invoke(Method.java:585)
       at
org.mule.impl.model.resolvers.DynamicEntryPoint.invokeMethod(DynamicEntryPoint.java:312)
       at
org.mule.impl.model.resolvers.DynamicEntryPoint.invoke(DynamicEntryPoint.java:259)
       at
org.mule.impl.DefaultLifecycleAdapter.intercept(DefaultLifecycleAdapter.java:194)
       at
org.mule.impl.InterceptorsInvoker.execute(InterceptorsInvoker.java:47)
       at
org.mule.impl.model.DefaultMuleProxy.run(DefaultMuleProxy.java:467)
       at org.mule.impl.work.WorkerContext.run(WorkerContext.java:310)
       at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
       at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
       at java.lang.Thread.run(Thread.java:595)
********************************************************************************
Then later we start receiving the problems below.