[
https://issues.apache.org/jira/browse/CAMEL-16704?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Claus Ibsen updated CAMEL-16704:
--------------------------------
Summary: camel-ahc - Requests getting timed out because the threads
assigned to channels are busy (was: Requests getting timed out because the
threads assigned to channels are busy. [component :: CAMEL-AHC] )
> camel-ahc - Requests getting timed out because the threads assigned to
> channels are busy
> ----------------------------------------------------------------------------------------
>
> 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, 3.1.0, 3.10.0
> Reporter: Sreejith Veluvil
> Priority: Minor
> Attachments: Camel-AHC_Thread_Busy_Issue.zip,
> Camel_AHC_Thread_Busy_31X_310X.zip
>
>
> 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)
