[
https://issues.apache.org/jira/browse/CAMEL-16704?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Sreejith Veluvil updated CAMEL-16704:
-------------------------------------
Attachment: (was: Petrobras_Issue_Test_Cases.zip)
> Requests getting timed out because the threads assigned to channels are busy.
> [component :: CAMEL-AHC]
> -------------------------------------------------------------------------------------------------------
>
> Key: CAMEL-16704
> URL: https://issues.apache.org/jira/browse/CAMEL-16704
> Project: Camel
> Issue Type: Bug
> Components: camel-ahc
> Affects Versions: 2.17.0, 2.24.3, 3.0.1
> Reporter: Sreejith Veluvil
> Priority: Major
>
> Hi,
> Requests are getting timed out while waiting for the threads assigned to a
> channel because the thread is busy executing some other work.
> Below is a simple camel route with a processor to imitate a long running
> activity by sleeping thread, camel-ahc component, and a processor to log the
> output. The above steps are running in a loop for two times.
> Direct(source) -> Loop (2) ->
>
> Processor to imitate a long running activity -> AHC component
> -> Processor to log body -> Mock Output
> I fired two async calls with a small delay between them. For the first call,
> after completing the long running activity, the message reached AHC
> component. The response was received and it was processed successfully by the
> Netty thread. After this all the activities are done by Netty thread and it
> starts processing the long running activity (since it is running in a loop).
> Meanwhile, the call with the second message completed the long running
> activity and message will reach the AHC component. Netty will assign the same
> channel which was assigned to the first message. Now it will wait for the
> thread to be available to process the response and this thread is busy
> performing the long running activity and eventually the requests times out.
> Below are some important logs I extracted from the version 2.24.3. From the
> logs, it is clear that the channel with id '0xbc4290ed' is assigned for both
> HTTP calls and request times out waiting for the thread named
> 'AHC-NETTY-COMMON-1-1'.
> I have attached JUnits for all 3 versions with folder name '217', '224' and
> '301'. Each folder will have JUnit for that particular version, Detailed
> TRACE log named 'Detailed_Logs_XXX.log' and important logs I extracted in a
> file named 'Important_Logs.txt'
> 17:44:38| Camel (camel-1) thread #1 - ProducerTemplate | ThreadDelay.java 39
> ## Camel (camel-1) thread #1 - ProducerTemplate going into sleep... Exchange
> Id :: ID-W-PF26MQZL-1622808877625-0-1.
> 17:44:38| Camel (camel-1) thread #1 - ProducerTemplate | ThreadDelay.java
> 39 ## Camel (camel-1) thread #1 - ProducerTemplate going into sleep...
> Exchange Id :: ID-W-PF26MQZL-1622808877625-0-1.
> 17:44:41| Camel (camel-1) thread #2 - ProducerTemplate |
> ThreadDelay.java 39 ## Camel (camel-1) thread #2 - ProducerTemplate going
> into sleep... Exchange Id :: ID-W-PF26MQZL-1622808877625-0-2.
> =17:44:42| Camel (camel-1) thread #1 -
> ProducerTemplate | ThreadDelay.java 41 ## Camel (camel-1) thread #1 -
> ProducerTemplate woke up from sleep... Exchange Id ::
> ID-W-PF26MQZL-1622808877625-0-1.
> =17:44:42| Camel (camel-1) thread #1 - ProducerTemplate | AhcProducer.java 53
> ## Executing request [https://www.boredapi.com/api/activity] GET headers:
> breadcrumbId:ID-W-PF26MQZL-1622808877625-0-1 17:44:44|
> AHC-NETTY-COMMON-1-1 | NettyConnectListener.java 73 ## Using new Channel
> '[id: 0xbc4290ed, L:/10.16.84.166:62334 -
> R:www.boredapi.com/34.201.80.84:443]' for 'GET' to '/api/activity'
> 17:44:44| AHC-NETTY-COMMON-1-1 | ThreadDelay.java 48 ##
> AHC-NETTY-COMMON-1-1 Exchange Id :: ID-W-PF26MQZL-1622808877625-0-1 :: Body
> received :: \{"activity":"Have a picnic with some
> friends","type":"social","participants":3,"price":0.1,"link":"","key":"6813070","accessibility":0.1}.
> 17:44:44| AHC-NETTY-COMMON-1-1 |
> ThreadDelay.java 39 ## AHC-NETTY-COMMON-1-1 going into sleep... Exchange Id
> :: ID-W-PF26MQZL-1622808877625-0-1.
> 17:44:44| Camel
> (camel-1) thread #2 - ProducerTemplate | ThreadDelay.java 41 ## Camel
> (camel-1) thread #2 - ProducerTemplate woke up from sleep... Exchange Id ::
> ID-W-PF26MQZL-1622808877625-0-2.
> 17:44:44| Camel (camel-1) thread #2 - ProducerTemplate | AhcProducer.java 53
> ## Executing request [https://www.boredapi.com/api/activity] GET headers:
> breadcrumbId:ID-W-PF26MQZL-1622808877625-0-2 17:44:44|
> Camel (camel-1) thread #2 - ProducerTemplate | NettyRequestSender.java 579 ##
> Using pooled Channel '[id: 0xbc4290ed, L:/10.16.84.166:62334 -
> R:www.boredapi.com/34.201.80.84:443]' for 'GET' to
> '[https://www.boredapi.com/api/activity']
>
> 17:44:48| pool-1-thread-1 | TimeoutTimerTask.java 42 ## Request timeout to
> www.boredapi.com/34.201.80.84:443 after 3000 ms for
> NettyResponseFuture{currentRetry=0,
> 17:44:48|
> AHC-NETTY-COMMON-1-1 | ThreadDelay.java 41 ## AHC-NETTY-COMMON-1-1 woke up
> from sleep... Exchange Id :: ID-W-PF26MQZL-1622808877625-0-1.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
