Application hangs when sending message to channel with outbound-channel-adapter

[mjkrumlauf]

My application hangs when a message is handled by the outbound-channel-adapter.

The application calls the method 'alert' as configured in the gateway below in my.AlertService. The service-activator receives the message and returns the XML representation of the object passed in the message payload to the output-channel. The outbound-channel-adapter successfully writes a message to the file system in the configured directory, but then the application hangs and the scheduler no longer executes at the interval specified by fixed-delay. I am at a loss as to what could be causing this problem.

   
        ...
        <task:scheduler id="harvesterScheduler" pool-size="2" />

        <task:scheduled-tasks scheduler="harvesterScheduler">
                <task:scheduled ref="loginHistoryHarvester" method="harvest"
                        fixed-delay="${loginHistory.pollDelayMillis}" />
        </task:scheduled-tasks>

         ...
     
        <int:channel id="objectAlertOut"/>

         <int:logging-channel-adapter id="logger" level="DEBUG"/>

        <int:channel id="xmlAlertOut">
            <int:interceptors>
               <int:wire-tap channel="logger"/>
            </int:interceptors>
        </int:channel>

        <int-file:outbound-channel-adapter
               id="temporary"
               channel="xmlAlertOut"
               auto-create-directory="true"
               directory="/home/xxx/outmsgs"/>

        <int:gateway id="alertProducer"
                service-interface="my.AlertService"
                default-request-channel="objectAlertOut" />

        <int:service-activator input-channel="objectAlertOut"
                                                   output-channel="xmlAlertOut"
                                                   ref="xmlAlertConsumer"
                                                   method="alert" />

Here's the trace (sanitized):

2010-06-24 19:13:18,260 DEBUG DirectChannel - preSend on channel 'objectAlertOut', message: [Payload=SomeAlertType [ip=172.16.12.21, logins=LoginsType [login=[gcardile, gcardile, clowenstine, pageeadmin, pageeadmin, cjerniganadmin, ashuleradmin, ahmadmoore, sspurlockadmin]], numlogins=9, time=2010-06-24 19:11:38.41]][Headers={$id=91d9b94a-0f16-456d-a56d-39ce0c3d18f3, $errorChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $replyChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $history=[alertProducer, channel:objectAlertOut], $timestamp=1277406798258}]
2010-06-24 19:13:18,261 DEBUG ServiceActivatingHandler - ServiceActivator for [my.app.alert.XmlAlertConsumer.alert]] received message: [Payload=SomeAlertType ]][Headers={$id=91d9b94a-0f16-456d-a56d-39ce0c3d18f3, $errorChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $replyChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $history=[alertProducer, channel:objectAlertOut], $timestamp=1277406798258}]
2010-06-24 19:13:18,299 DEBUG ServiceActivatingHandler - handler 'ServiceActivator for [my.app.alert.XmlAlertConsumer.alert]]' sending reply Message: [Payload=<xxxxxx></xxxxxx>][Headers={$id=1631234c-99fa-4154-85d7-ac7d925aa99b, $errorChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $history=[alertProducer, channel:objectAlertOut], $replyChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $timestamp=1277406798299}]
2010-06-24 19:13:18,299 DEBUG DirectChannel - preSend on channel 'xmlAlertOut', message: [Payload=<xxxxxx></xxxxxx>][Headers={$id=1631234c-99fa-4154-85d7-ac7d925aa99b, $errorChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $history=[alertProducer, channel:objectAlertOut, channel:xmlAlertOut], $replyChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $timestamp=1277406798299}]
2010-06-24 19:13:18,299 DEBUG DirectChannel - preSend on channel 'logger', message: [Payload=<xxxxxx></xxxxxx>][Headers={$id=1631234c-99fa-4154-85d7-ac7d925aa99b, $errorChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $history=[alertProducer, channel:objectAlertOut, channel:xmlAlertOut, channel:logger], $replyChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $timestamp=1277406798299}]
2010-06-24 19:13:18,299 DEBUG LoggingHandler - org.springframework.integration.handler.LoggingHan dler#0 received message: [Payload=<xxxxxx></xxxxxx>][Headers={$id=1631234c-99fa-4154-85d7-ac7d925aa99b, $errorChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $history=[alertProducer, channel:objectAlertOut, channel:xmlAlertOut, channel:logger, logging-channel-adapter:logger.adapter], $replyChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $timestamp=1277406798299}]
2010-06-24 19:13:18,300 DEBUG LoggingHandler - <xxxxxx></xxxxxx>
2010-06-24 19:13:18,300 DEBUG DirectChannel - postSend (sent=true) on channel 'logger', message: [Payload=<xxxxxx></xxxxxx>][Headers={$id=1631234c-99fa-4154-85d7-ac7d925aa99b, $errorChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $history=[alertProducer, channel:objectAlertOut, channel:xmlAlertOut, channel:logger, logging-channel-adapter:logger.adapter], $replyChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $timestamp=1277406798299}]
2010-06-24 19:13:18,300 DEBUG FileWritingMessageHandler - org.springframework.integration.file.FileWritingMe ssageHandler@635adc6 received message: [Payload=<xxxxxx></xxxxxx>][Headers={$id=1631234c-99fa-4154-85d7-ac7d925aa99b, $errorChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $history=[alertProducer, channel:objectAlertOut, channel:xmlAlertOut, channel:logger, logging-channel-adapter:logger.adapter, temporary], $replyChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $timestamp=1277406798299}]
2010-06-24 19:13:18,301 DEBUG FileWritingMessageHandler - handler 'org.springframework.integration.file.FileWritingM essageHandler@635adc6' sending reply Message: [Payload=/home/mkrumlauf/fadmonitor/outmsgs/1631234c-99fa-4154-85d7-ac7d925aa99b.msg][Headers={$id=e1a26a50-772e-4277-88d6-ffb7caeeb154, $errorChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $replyChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $history=[alertProducer, channel:objectAlertOut, channel:xmlAlertOut, channel:logger, logging-channel-adapter:logger.adapter, temporary], $timestamp=1277406798301}]
2010-06-24 19:13:18,301 DEBUG NullChannel - message sent to null channel: [Payload=/home/mkrumlauf/fadmonitor/outmsgs/1631234c-99fa-4154-85d7-ac7d925aa99b.msg][Headers={$id=e1a26a50-772e-4277-88d6-ffb7caeeb154, $errorChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $replyChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $history=[alertProducer, channel:objectAlertOut, channel:xmlAlertOut, channel:logger, logging-channel-adapter:logger.adapter, temporary], $timestamp=1277406798301}]
2010-06-24 19:13:18,301 DEBUG DirectChannel - postSend (sent=true) on channel 'xmlAlertOut', message: [Payload=<xxxxxx></xxxxxx>][Headers={$id=1631234c-99fa-4154-85d7-ac7d925aa99b, $errorChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $history=[alertProducer, channel:objectAlertOut, channel:xmlAlertOut, channel:logger, logging-channel-adapter:logger.adapter, temporary], $replyChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $timestamp=1277406798299}]
2010-06-24 19:13:18,302 DEBUG DirectChannel - postSend (sent=true) on channel 'objectAlertOut', message: [Payload=SomeAlertType [ip=172.16.12.21, logins=LoginsType [login=[gcardile, gcardile, clowenstine, pageeadmin, pageeadmin, cjerniganadmin, ashuleradmin, ahmadmoore, sspurlockadmin]], numlogins=9, time=2010-06-24 19:11:38.41]][Headers={$id=91d9b94a-0f16-456d-a56d-39ce0c3d18f3, $errorChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $replyChannel=org.springframework.integration.chan nel.MessageChannelTemplate$TemporaryReplyChannel@e 26db62, $history=[alertProducer, channel:objectAlertOut, channel:xmlAlertOut, channel:logger, logging-channel-adapter:logger.adapter, temporary], $timestamp=1277406798258}

[iwein]

It looks from the logs that the application did its work as designed. So my first investigation would be to check why no new messages are being sent to 'objectAlertOut'.

Why do you say the application is hanging? Did you make a thread dump? (you can run jstack against the running process to see the stacks and check to see if threads are actually blocked on something).

But as I said, my first thought is that it's just not getting anything new to process.

[mjkrumlauf]

It appears that my application is hanging when the gateway proxy on receiving - here's the thread dump:

Thread 3573: (state = BLOCKED)
- sun.misc.Unsafe.park(boolean, long) @bci=0 (Interpreted frame)
- java.util.concurrent.locks.LockSupport.park() @bci=5 (Interpreted frame)
- java.util.concurrent.locks.AbstractQueuedSynchroni zer.parkAndCheckInterrupt() @bci=0 (Interpreted frame)
- java.util.concurrent.locks.AbstractQueuedSynchroni zer.doAcquireSharedInterruptibly(int) @bci=54 (Interpreted frame)
- java.util.concurrent.locks.AbstractQueuedSynchroni zer.acquireSharedInterruptibly(int) @bci=24 (Interpreted frame)
- java.util.concurrent.CountDownLatch.await() @bci=5 (Interpreted frame)
- org.springframework.integration.channel.MessageCha nnelTemplate$TemporaryReplyChannel.receive(long) @bci=13, line=298 (Interpreted frame)
- org.springframework.integration.channel.MessageCha nnelTemplate$TemporaryReplyChannel.receive() @bci=4, line=292 (Interpreted frame)
- org.springframework.integration.channel.MessageCha nnelTemplate.doReceive(org.springframework.integra tion.channel.PollableChannel) @bci=28, line=236 (Interpreted frame)
- org.springframework.integration.channel.MessageCha nnelTemplate.doSendAndReceive(org.springframework. integration.core.Message, org.springframework.integration.core.MessageChanne l) @bci=76, line=254 (Interpreted frame)
- org.springframework.integration.channel.MessageCha nnelTemplate.sendAndReceive(org.springframework.in tegration.core.Message, org.springframework.integration.core.MessageChanne l) @bci=30, line=216 (Interpreted frame)
- org.springframework.integration.gateway.AbstractMe ssagingGateway.sendAndReceiveMessage(org.springfra mework.integration.core.Message) @bci=55, line=177 (Interpreted frame)
- org.springframework.integration.gateway.AbstractMe ssagingGateway.sendAndReceive(java.lang.Object, boolean) @bci=8, line=160 (Interpreted frame)
- org.springframework.integration.gateway.AbstractMe ssagingGateway.sendAndReceive(java.lang.Object) @bci=3, line=151 (Interpreted frame)
- org.springframework.integration.gateway.GatewayPro xyFactoryBean.invokeGatewayMethod(org.aopalliance. intercept.MethodInvocation) @bci=131, line=232 (Interpreted frame)
- org.springframework.integration.gateway.GatewayPro xyFactoryBean.invoke(org.aopalliance.intercept.Met hodInvocation) @bci=55, line=201 (Interpreted frame)
- org.springframework.aop.framework.ReflectiveMethod Invocation.proceed() @bci=101, line=172 (Interpreted frame)
- org.springframework.aop.framework.JdkDynamicAopPro xy.invoke(java.lang.Object, java.lang.reflect.Method, java.lang.Object[]) @bci=321, line=202 (Interpreted frame)
- $Proxy11.alert(my.util.Marshalable) @bci=16 (Interpreted frame)
- my.listener.AbstractAlertProducerListener.alert(my .util.Marshalable) @bci=14, line=34 (Interpreted frame) - my.listener.IpAttackListener.update(com.espertech. esper.client.EventBean[], com.espertech.esper.client.EventBean[]) @bci=42, line=41 (Interpreted frame)
- com.espertech.esper.core.StatementResultServiceImp l.processDispatch(com.espertech.esper.collection.U niformPair) @bci=87, line=237 (Interpreted frame)
- com.espertech.esper.core.StatementResultServiceImp l.execute() @bci=127, line=213 (Interpreted frame)
- com.espertech.esper.core.UpdateDispatchViewBase.ex ecute() @bci=15, line=75 (Interpreted frame)
- com.espertech.esper.core.UpdateDispatchFutureSpin. execute() @bci=74, line=85 (Interpreted frame)
- com.espertech.esper.dispatch.DispatchServiceImpl.d ispatchFromQueue(com.espertech.esper.collection.Ar rayDequeJDK6Backport) @bci=71, line=57 (Interpreted frame)
- com.espertech.esper.dispatch.DispatchServiceImpl.d ispatch() @bci=9, line=31 (Interpreted frame)
- com.espertech.esper.core.EPRuntimeImpl.dispatch() @bci=7, line=1043 (Interpreted frame)
- com.espertech.esper.core.EPRuntimeImpl.processTime Event(com.espertech.esper.client.time.TimerEvent) @bci=203, line=465 (Interpreted frame)
- com.espertech.esper.core.EPRuntimeImpl.processEven t(java.lang.Object) @bci=12, line=365 (Interpreted frame)
- com.espertech.esper.core.EPRuntimeImpl.sendEvent(j ava.lang.Object) @bci=119, line=210 (Interpreted frame)
- my.framework.SimulatedTimeEsperBean.sendEvent(my.e vent.AlertEvent) @bci=30, line=31 (Interpreted frame)
- my.event.EventGenerator.execute(java.lang.Object) @bci=22, line=37 (Interpreted frame)
- org.apache.commons.collections.functors.ChainedClo sure.execute(java.lang.Object) @bci=18, line=119 (Interpreted frame)
- org.apache.commons.collections.CollectionUtils.for AllDo(java.util.Collection, org.apache.commons.collections.Closure) @bci=31, line=389 (Interpreted frame)
- my.harvester.LoginHistoryHarvester.generateEventsA fter(my.generated.LastLoginHistoryIdType) @bci=30, line=71 (Interpreted frame)
- my.harvester.LoginHistoryHarvester.harvest() @bci=20, line=45 (Interpreted frame)
- sun.reflect.GeneratedMethodAccessor19.invoke(java. lang.Object, java.lang.Object[]) @bci=36 (Interpreted frame)
- sun.reflect.DelegatingMethodAccessorImpl.invoke(ja va.lang.Object, java.lang.Object[]) @bci=6 (Interpreted frame)
Error occurred during stack walking:

[iwein]

This is a call blocked waiting on a reply message from a temporary channel. If this is indeed a bug, it should be reproducible by wiring the following:

gateway -> file:outbound-channel-adapter

Can you include the code for AlertService, or better yet a small project that demonstrates the problem? My hunch is that it will not block when you make AlertService.* return void.