[
https://issues.apache.org/jira/browse/CAMEL-16704?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Sreejith Veluvil updated CAMEL-16704:
-------------------------------------
Description:
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.
was:
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.
> 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: Minor
> Attachments: Camel-AHC_Thread_Busy_Issue.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)
