Sreejith Veluvil created CAMEL-16704:
----------------------------------------
Summary: Requests getting timed out because the threads assigned
to channels are busy in CAMEL-AHC component
Key: CAMEL-16704
URL: https://issues.apache.org/jira/browse/CAMEL-16704
Project: Camel
Issue Type: Bug
Components: camel-ahc
Affects Versions: 3.0.1, 2.24.3, 2.17.0
Reporter: Sreejith Veluvil
Attachments: Petrobras_Issue_Test_Cases.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)
