Hi,
I think I may have run into a potential issue with camel-ahc. I've narrowed it
down to a very specific scenario - a combination of re-using the same ahc
component in combination with using split().parallelProcessing() EIP. Tested
with camel 2.14.1 and 2.14.0.
I'll try and demonstrate in a simple route:
List<String> list = Arrays.asList("alice", "bob", "charles", "david",
"edward");
from("timer://foo?repeatCount=1")
.setBody(constant("someMainRouteContent"))
.to("direct:fetch") //
[1]
.setBody(constant(list))
.split(body()).parallelProcessing() // [2]
.log("processing ${body}")
.to("direct:fetch") //
[3]
.end()
.log("and back to main processing")
.end();
from("direct:fetch")
.log("making http request for ${body}")
.to("ahc:http://localhost:8765/rest/test";)
.log("returned from http request for ${body}")
.end();
Note:
1. The routes share the same AHC component [1, 3] (i.e. common set of ahc
worker threads).
2. The ahc worker thread will continue processing synchronously between [1] and
[2],until the point the split() parallel thread pool takes over. On an http
response, the ahc worker thread will continue processing synchronouslyas
expected.
3. The above will result in a timeout exception for one of the split exchanges
(irrespective of the size of the list), and the route never completes.
java.util.concurrent.TimeoutException: Request timeout of 60000 ms
at
com.ning.http.client.providers.netty.timeout.TimeoutTimerTask.expire(TimeoutTimerTask.java:43)
at
com.ning.http.client.providers.netty.timeout.RequestTimeoutTimerTask.run(RequestTimeoutTimerTask.java:41)
at
org.jboss.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:556)
at
org.jboss.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:632)
at
org.jboss.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:369)
at
org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
at java.lang.Thread.run(Thread.java:722)
Log output for the above route is attached.
Having two separate ahc endpoints (i.e. with separate thread pools), or without
parallel processing in the split EIP, then the above works fine.
Any thoughts?
Kind Regards,
Elvio
13:53:09.757{UTC} [ main] DefaultCamelContext
INFO Apache Camel 2.14.1 (CamelContext: camel-1) started in 0.949 seconds
13:53:10.772{UTC} [mel-1) thread #0 - timer://foo] route5
INFO making http request for someMainRouteContent
13:53:11.906{UTC} [ qtp202392075-23] route3
INFO Finished with rest request
13:53:11.930{UTC} [ New I/O worker #1] route5
INFO returned from http request for someMainRouteContent
13:53:11.940{UTC} [el (camel-1) thread #5 - Split] route4
INFO processing david
13:53:11.940{UTC} [el (camel-1) thread #6 - Split] route4
INFO processing edward
13:53:11.940{UTC} [el (camel-1) thread #6 - Split] route5
INFO making http request for edward
13:53:11.940{UTC} [el (camel-1) thread #1 - Split] route4
INFO processing alice
13:53:11.941{UTC} [el (camel-1) thread #1 - Split] route5
INFO making http request for alice
13:53:11.940{UTC} [el (camel-1) thread #2 - Split] route4
INFO processing bob
13:53:11.945{UTC} [el (camel-1) thread #2 - Split] route5
INFO making http request for bob
13:53:11.940{UTC} [el (camel-1) thread #4 - Split] route4
INFO processing charles
13:53:11.947{UTC} [el (camel-1) thread #4 - Split] route5
INFO making http request for charles
13:53:11.940{UTC} [el (camel-1) thread #5 - Split] route5
INFO making http request for david
13:53:12.944{UTC} [ qtp202392075-26] route3
INFO Finished with rest request
13:53:12.953{UTC} [ qtp202392075-21] route3
INFO Finished with rest request
13:53:12.953{UTC} [ New I/O worker #2] route5
INFO returned from http request for alice
13:53:12.954{UTC} [ qtp202392075-22] route3
INFO Finished with rest request
13:53:12.957{UTC} [ New I/O worker #4] route5
INFO returned from http request for charles
13:53:12.965{UTC} [ New I/O worker #3] route5
INFO returned from http request for bob
13:54:11.983{UTC} [ Hashed wheel timer #2] DefaultErrorHandler
ERROR Failed delivery for (MessageId: ID-XXXX-52545-1422625988470-0-5 on
ExchangeId: ID-XXXX-52545-1422625988470-0-8). Exhausted after delivery attempt:
1 caught: java.util.concurrent.TimeoutException: Request timeout of 60000 ms
Message History
---------------------------------------------------------------------------------------------------------------------------------------
RouteId ProcessorId Processor
Elapsed (ms)
[route4 ] [route4 ] [timer://foo?repeatCount=1
] [ 61217]
[route4 ] [log2 ] [log
] [ 0]
[route4 ] [to4 ] [direct:fetch
] [ 60039]
[route5 ] [log4 ] [log
] [ 0]
[route5 ] [to5 ] [ahc:http://localhost:8765/rest/test
] [ 60039]
Exchange
---------------------------------------------------------------------------------------------------------------------------------------
Exchange[
Id ID-XXXX-52545-1422625988470-0-8
ExchangePattern InOnly
Headers {Accept=*/*,
breadcrumbId=ID-XXXX-52545-1422625988470-0-1, CamelHttpResponseCode=200,
CamelRedelivered=false, CamelRedeliveryCounter=0, Content-Length=20,
Content-Type=, firedTime=Fri Jan 30 13:53:10 GMT 2015,
Server=Jetty(8.1.15.v20140411), Transfer-Encoding=chunked, User-Agent=NING/1.0}
BodyType String
Body edward
]
Stacktrace
---------------------------------------------------------------------------------------------------------------------------------------
java.util.concurrent.TimeoutException: Request timeout of 60000 ms
at
com.ning.http.client.providers.netty.timeout.TimeoutTimerTask.expire(TimeoutTimerTask.java:43)
at
com.ning.http.client.providers.netty.timeout.RequestTimeoutTimerTask.run(RequestTimeoutTimerTask.java:41)
at
org.jboss.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:556)
at
org.jboss.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:632)
at
org.jboss.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:369)
at
org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
at java.lang.Thread.run(Thread.java:722)
