[CAMEL-2540] async route not working with Mina

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.2.0
• Fix Version/s: 2.3.0
• Component/s: camel-core, camel-mina

Environment

tomcat

• Assignee: Claus Ibsen
• Reporter: Anand
• Created: 11/Mar/10 15:33
• Updated: 24/Apr/11 10:01
• Resolved: 22/Mar/10 09:28

Description

here is my route:

from("mina:tcp://localhost:6202?textline=true&sync=true").process(new Processor() {
public void process(Exchange exchange) throws Exception

{ String body = exchange.getIn().getBody(String.class); Thread.sleep(5000); exchange.getOut().setBody("Bye 1" + body); }

});

from("file:///test/test/response")
.convertBodyTo(String.class)//.threads(1)
.toAsync("mina:tcp://localhost:6202?sync=true&textline=true",10)
.to("log:+++ reply++++");

here is the output, you can see all reply logs have a same message body and async process is releasing all threads at the first response, this is probably Mina component bug in the context of aync route.

2010-03-11 10:21:16,405 [Camel thread 11: FileComponent] FileConsumer DEBUG Total 3 files to consume
2010-03-11 10:21:16,405 [Camel thread 11: FileComponent] FileConsumer DEBUG About to process file: GenericFile[C:\test\test\response\Copy (2) of New Text Document (3).txt] using exchange: Exchange[GenericFileMessage with file: GenericFile[C:\test\test\response\Copy (2) of New Text Document (3).txt]]
2010-03-11 10:21:16,452 [Camel thread 11: FileComponent] DefaultManagementAgent DEBUG Registered MBean with objectname: org.apache.camel:context=tamlft0spj1/cameltest,type=producers,name=MinaProducer(0x2e6c66)
2010-03-11 10:21:16,452 [Camel thread 11: FileComponent] MinaProducer DEBUG Starting producer: Producer[mina://tcp://localhost:6202?sync=true&textline=true]
2010-03-11 10:21:16,452 [Camel thread 11: FileComponent] ProducerCache DEBUG Adding to producer service pool with key: Endpoint[mina://tcp://localhost:6202?sync=true&textline=true] for producer: Producer[mina://tcp://localhost:6202?sync=true&textline=true]
2010-03-11 10:21:16,452 [2: SendAsyncProcessor-Producer] MinaProducer DEBUG Creating connector to address: localhost/127.0.0.1:6202 using connector: org.apache.mina.transport.socket.nio.SocketConnector@16cefa8 timeout: 30000 millis.
2010-03-11 10:21:16,452 [Camel thread 11: FileComponent] FileConsumer DEBUG About to process file: GenericFile[C:\test\test\response\Copy of New Text Document (3).txt] using exchange: Exchange[GenericFileMessage with file: GenericFile[C:\test\test\response\Copy of New Text Document (3).txt]]
2010-03-11 10:21:16,467 [3: SendAsyncProcessor-Producer] MinaProducer DEBUG Creating connector to address: localhost/127.0.0.1:6202 using connector: org.apache.mina.transport.socket.nio.SocketConnector@16cefa8 timeout: 30000 millis.
2010-03-11 10:21:16,467 [Camel thread 11: FileComponent] FileConsumer DEBUG About to process file: GenericFile[C:\test\test\response\New Text Document (3).txt] using exchange: Exchange[GenericFileMessage with file: GenericFile[C:\test\test\response\New Text Document (3).txt]]
2010-03-11 10:21:16,467 [4: SendAsyncProcessor-Producer] MinaProducer DEBUG Creating connector to address: localhost/127.0.0.1:6202 using connector: org.apache.mina.transport.socket.nio.SocketConnector@16cefa8 timeout: 30000 millis.
2010-03-11 10:21:16,499 [SocketConnectorIoProcessor-0.1] ExecutorFilter DEBUG Launching thread for localhost/127.0.0.1:6202
2010-03-11 10:21:16,499 [ SocketAcceptorIoProcessor-0.0] ExecutorFilter DEBUG Launching thread for /127.0.0.1:3362
2010-03-11 10:21:16,499 [ SocketAcceptorIoProcessor-0.1] ExecutorFilter DEBUG Launching thread for /127.0.0.1:3363
2010-03-11 10:21:16,499 [SocketConnectorIoProcessor-0.0] ExecutorFilter DEBUG Launching thread for localhost/127.0.0.1:6202
2010-03-11 10:21:16,499 [ SocketAcceptorIoProcessor-0.2] ExecutorFilter DEBUG Launching thread for /127.0.0.1:3374
2010-03-11 10:21:16,499 [SocketConnectorIoProcessor-0.2] ExecutorFilter DEBUG Launching thread for localhost/127.0.0.1:6202
2010-03-11 10:21:16,514 [amel thread 22: MinaThreadPool] ExecutorFilter DEBUG Exiting since queue is empty for /127.0.0.1:3363
2010-03-11 10:21:16,514 [amel thread 24: MinaThreadPool] ExecutorFilter DEBUG Exiting since queue is empty for /127.0.0.1:3362
2010-03-11 10:21:16,514 [amel thread 23: MinaThreadPool] ExecutorFilter DEBUG Exiting since queue is empty for localhost/127.0.0.1:6202
2010-03-11 10:21:16,514 [2: SendAsyncProcessor-Producer] MinaProducer DEBUG Writing body : hello2
2010-03-11 10:21:16,514 [3: SendAsyncProcessor-Producer] MinaProducer DEBUG Writing body : hello3
2010-03-11 10:21:16,514 [amel thread 26: MinaThreadPool] ExecutorFilter DEBUG Exiting since queue is empty for /127.0.0.1:3374
2010-03-11 10:21:16,514 [amel thread 25: MinaThreadPool] ExecutorFilter DEBUG Exiting since queue is empty for localhost/127.0.0.1:6202
2010-03-11 10:21:16,514 [amel thread 27: MinaThreadPool] ExecutorFilter DEBUG Exiting since queue is empty for localhost/127.0.0.1:6202
2010-03-11 10:21:16,514 [4: SendAsyncProcessor-Producer] MinaProducer DEBUG Writing body : hello1
2010-03-11 10:21:16,514 [SocketConnectorIoProcessor-0.2] ExecutorFilter DEBUG Launching thread for localhost/127.0.0.1:6202
2010-03-11 10:21:16,514 [3: SendAsyncProcessor-Producer] MinaProducer DEBUG Waiting for response
2010-03-11 10:21:16,530 [2: SendAsyncProcessor-Producer] MinaProducer DEBUG Waiting for response
2010-03-11 10:21:16,530 [4: SendAsyncProcessor-Producer] MinaProducer DEBUG Waiting for response
2010-03-11 10:21:16,530 [ SocketAcceptorIoProcessor-0.2] ExecutorFilter DEBUG Launching thread for /127.0.0.1:3374
2010-03-11 10:21:16,530 [amel thread 27: MinaThreadPool] ExecutorFilter DEBUG Exiting since queue is empty for localhost/127.0.0.1:6202
2010-03-11 10:21:16,530 [amel thread 26: MinaThreadPool] MinaConsumer DEBUG Received body: hello2
2010-03-11 10:21:21,530 [amel thread 26: MinaThreadPool] MinaConsumer DEBUG Writing body: Bye 1hello2
2010-03-11 10:21:21,530 [SocketConnectorIoProcessor-0.2] ExecutorFilter DEBUG Launching thread for localhost/127.0.0.1:6202
2010-03-11 10:21:21,530 [amel thread 27: MinaThreadPool] MinaProducer DEBUG Message received: Bye 1hello2
2010-03-11 10:21:21,530 [amel thread 27: MinaThreadPool] ExecutorFilter DEBUG Exiting since queue is empty for localhost/127.0.0.1:6202
2010-03-11 10:21:21,530 [amel thread 26: MinaThreadPool] MinaConsumer DEBUG Received body: hello3
2010-03-11 10:21:21,530 [:6202?sync=true&textline=true]] SendProcessor DEBUG Async reply received now routing the Exchange: Exchange[Message: Bye 1hello2]
2010-03-11 10:21:21,530 [:6202?sync=true&textline=true]] SendProcessor DEBUG Async reply received now routing the Exchange: Exchange[Message: Bye 1hello2]
2010-03-11 10:21:21,530 [:6202?sync=true&textline=true]] SendProcessor DEBUG Async reply received now routing the Exchange: Exchange[Message: Bye 1hello2]
2010-03-11 10:21:21,546 [:6202?sync=true&textline=true]] DefaultManagementAgent DEBUG Registered MBean with objectname: org.apache.camel:context=tamlft0spj1/cameltest,type=producers,name=Producer(0x16321e6)
2010-03-11 10:21:21,546 [:6202?sync=true&textline=true]] ProcessorEndpoint$1 DEBUG Starting producer: Producer[log://+++ reply++++]
2010-03-11 10:21:21,546 [:6202?sync=true&textline=true]] ProducerCache DEBUG Adding to producer cache with key: Endpoint[log://+++ reply++++] for producer: Producer[log://+++ reply++++]
2010-03-11 10:21:21,546 [:6202?sync=true&textline=true]] +++ reply++++ INFO Exchange[BodyType:String, Body:Bye 1hello2]
2010-03-11 10:21:21,546 [:6202?sync=true&textline=true]] GenericFileOnCompletion DEBUG Done processing file: GenericFile[C:\test\test\response\Copy (2) of New Text Document (3).txt] using exchange: Exchange[Message: Bye 1hello2]
2010-03-11 10:21:21,546 [:6202?sync=true&textline=true]] +++ reply++++ INFO Exchange[BodyType:String, Body:Bye 1hello2]
2010-03-11 10:21:21,546 [:6202?sync=true&textline=true]] GenericFileOnCompletion DEBUG Done processing file: GenericFile[C:\test\test\response\Copy of New Text Document (3).txt] using exchange: Exchange[Message: Bye 1hello2]
2010-03-11 10:21:21,546 [:6202?sync=true&textline=true]] FileUtil DEBUG Tried 1 to delete file: C:\test\test\response\Copy (2) of New Text Document (3).txt.camelLock with result: true
2010-03-11 10:21:21,561 [:6202?sync=true&textline=true]] +++ reply++++ INFO Exchange[BodyType:String, Body:Bye 1hello2]
2010-03-11 10:21:21,561 [:6202?sync=true&textline=true]] GenericFileOnCompletion DEBUG Done processing file: GenericFile[C:\test\test\response\New Text Document (3).txt] using exchange: Exchange[Message: Bye 1hello2]
2010-03-11 10:21:21,561 [:6202?sync=true&textline=true]] FileUtil DEBUG Tried 1 to delete file: C:\test\test\response\Copy of New Text Document (3).txt.camelLock with result: true
2010-03-11 10:21:21,561 [:6202?sync=true&textline=true]] nericFileRenameProcessStrategy DEBUG Renaming file: GenericFile[C:\test\test\response\Copy (2) of New Text Document (3).txt] to: GenericFile[C:\test\test\response\.camel\Copy (2) of New Text Document (3).txt]
2010-03-11 10:21:21,561 [:6202?sync=true&textline=true]] FileUtil DEBUG Tried 1 to delete file: C:\test\test\response\New Text Document (3).txt.camelLock with result: true
2010-03-11 10:21:21,561 [:6202?sync=true&textline=true]] nericFileRenameProcessStrategy DEBUG Renaming file: GenericFile[C:\test\test\response\Copy of New Text Document (3).txt] to: GenericFile[C:\test\test\response\.camel\Copy of New Text Document (3).txt]
2010-03-11 10:21:21,561 [:6202?sync=true&textline=true]] nericFileRenameProcessStrategy DEBUG Renaming file: GenericFile[C:\test\test\response\New Text Document (3).txt] to: GenericFile[C:\test\test\response\.camel\New Text Document (3).txt]
2010-03-11 10:21:21,561 [:6202?sync=true&textline=true]] FileUtil DEBUG Tried 1 to rename file: C:\test\test\response\Copy (2) of New Text Document (3).txt to: C:\test\test\response\.camel\Copy (2) of New Text Document (3).txt with result: true
2010-03-11 10:21:21,561 [:6202?sync=true&textline=true]] FileUtil DEBUG Tried 1 to rename file: C:\test\test\response\Copy of New Text Document (3).txt to: C:\test\test\response\.camel\Copy of New Text Document (3).txt with result: true
2010-03-11 10:21:21,577 [:6202?sync=true&textline=true]] FileUtil DEBUG Tried 1 to rename file: C:\test\test\response\New Text Document (3).txt to: C:\test\test\response\.camel\New Text Document (3).txt with result: true
2010-03-11 10:21:26,530 [amel thread 26: MinaThreadPool] MinaConsumer DEBUG Writing body: Bye 1hello3
2010-03-11 10:21:26,530 [amel thread 26: MinaThreadPool] MinaConsumer DEBUG Received body: hello1
2010-03-11 10:21:26,530 [SocketConnectorIoProcessor-0.2] ExecutorFilter DEBUG Launching thread for localhost/127.0.0.1:6202
2010-03-11 10:21:26,530 [amel thread 27: MinaThreadPool] MinaProducer DEBUG Message received: Bye 1hello3
2010-03-11 10:21:26,530 [amel thread 27: MinaThreadPool] ExecutorFilter DEBUG Exiting since queue is empty for localhost/127.0.0.1:6202
2010-03-11 10:21:31,531 [amel thread 26: MinaThreadPool] MinaConsumer DEBUG Writing body: Bye 1hello1
2010-03-11 10:21:31,531 [SocketConnectorIoProcessor-0.2] ExecutorFilter DEBUG Launching thread for localhost/127.0.0.1:6202
2010-03-11 10:21:31,531 [amel thread 26: MinaThreadPool] ExecutorFilter DEBUG Exiting since queue is empty for /127.0.0.1:3374
2010-03-11 10:21:31,531 [amel thread 27: MinaThreadPool] MinaProducer DEBUG Message received: Bye 1hello1
2010-03-11 10:21:31,531 [amel thread 27: MinaThreadPool] ExecutorFilter DEBUG Exiting since queue is empty for localhost/127.0.0.1:6202