Uploaded image for project: 'Camel'
  1. Camel
  2. CAMEL-16704

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

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Minor
    • Resolution: Fixed
    • 2.17.0, 2.24.3, 3.0.1, 3.1.0, 3.10.0
    • 3.11.1, 3.12.0
    • camel-ahc
    • None
    • Unknown

    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.

      Attachments

        1. Camel-AHC_Thread_Busy_Issue.zip
          249 kB
          Sreejith Veluvil
        2. Camel_AHC_Thread_Busy_31X_310X.zip
          266 kB
          Sreejith Veluvil

        Activity

          People

            davsclaus Claus Ibsen
            sveluvil Sreejith Veluvil
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: