Requests getting timed out because the threads assigned to channels are busy

[sveluvil]

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 request times out. The issue here was that the same channel was assigned to the request even when the thread bound to that channel is busy.

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 versions '2.24.3', '3.0.1', '3.1.0', and '3.10.0' with folder name '224', '301', '3.1.0' and '3.10.0' respectively. Each folder will have JUnit for that version, Detailed TRACE log named 'Detailed_Logs_XXX.log' and important logs I extracted in a file named 'Important_Logs_XXX.txt. Please check attachment 'AHC_Thread_Delay_Issue.zip'
AHC_Thread_Delay_Issue.zip

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.

[n-miles]

Am I interpreting this correctly in thinking that you're blocking a Netty thread on purpose?