I just took some investigating with this issue. It looks like that the "timeout" handler is removed and has not been added until the next request. So I proposal that 1) revert some part of the fix of CAMEL-14363 to add back the codes which removes the "timeout" handler after receiving the response. 2) add the "timeout" handler in the activateObject() which should be invoked by NettyProducerPoolableObjectFactory with the connection pool.
Vincenzo, can you provide a simple reproducer that I can use to verify my changes at first ? Thanks, Amos On Mon, Jun 15, 2020 at 7:39 PM Claus Ibsen <claus.ib...@gmail.com> wrote: > Hi > > On Mon, Jun 15, 2020 at 11:27 AM Zheng Feng <zf...@redhat.com> wrote: > > > > Feel free to assign the issue to me and I can take a look at it. > > > > Thanks I created a ticket > https://issues.apache.org/jira/browse/CAMEL-15195 > > > On Mon, Jun 15, 2020 at 5:22 PM Claus Ibsen <claus.ib...@gmail.com> > wrote: > > > > > Hi > > > > > > Yeah that may seem a bit weird too. Lets create a JIRA and investigate > > > > > > On Fri, Jun 12, 2020 at 10:07 AM Zheng Feng <zf...@redhat.com> wrote: > > > > > > > > It seems related to > https://issues.apache.org/jira/browse/CAMEL-14363. I > > > > just checked the PR [1] > > > > and it looks a little bit strange to delete the codes which remove > the > > > > timeout handler after receiving a response. > > > > > > > > [1] https://github.com/apache/camel/pull/3460 > > > > > > > > On Fri, Jun 12, 2020 at 3:38 PM Claus Ibsen <claus.ib...@gmail.com> > > > wrote: > > > > > > > > > Hi > > > > > > > > > > It smells like a bug, you are welcome to create a JIRA and if you > can > > > > > work on an unit test we can use as reproducer. > > > > > Also check the existing timeout tests in camel-netty. > > > > > > > > > > > > > > > On Wed, Jun 10, 2020 at 7:54 PM Vincenzo Galluccio > > > > > <vincenzo.gallucci...@gmail.com> wrote: > > > > > > > > > > > > Hello, > > > > > > > > > > > > I'm having a problem with Camel-Netty component version 3.3.0 > when > > > > > > using the requestTimeout option, which is causing the request to > > > > > > always timeout even when a response is received on time. > > > > > > The ReadTimeoutException should only be triggered if a response > is > > > not > > > > > > received on time. > > > > > > > > > > > > I have a Netty Producer Endpoint, in a Route, configured with > > > > > > requestTimeout set to 10000 ms, as follows: > > > > > > > > > > > > ``` > > > > > > @Component > > > > > > public class TransactionsRoute extends RouteBuilder { > > > > > > > > > > > > @Override > > > > > > public void configure() { > > > > > > > > > > > > from("direct:startRoute") > > > > > > > > > > > > > > > .to(netty:tcp://localhost:9999?sync=true&encoders=#encoders&decoders=#decoders&requestTimeout=10000); > > > > > > } > > > > > > } > > > > > > ``` > > > > > > > > > > > > See logs below which show that a request is sent at 15:20:10.996 > and > > > > > > response is received at 15:20:11.256, and the exception is > triggered > > > > > > at 15:20:21.260, which is 10 seconds after the response is > received > > > > > > (note: requestTimeout set to 10000 ms): > > > > > > > > > > > > ``` > > > > > > 2020-06-10 15:20:10.996 TRACE 29616 --- [ClientTCPWorker] > > > > > > o.a.camel.component.netty.NettyProducer : Channel open finished > with > > > > > > AbstractBootstrap$PendingRegistrationPromise@347574(success) > > > > > > 2020-06-10 15:20:10.996 DEBUG 29616 --- [ClientTCPWorker] > > > > > > o.a.camel.component.netty.NettyProducer : Creating connector to > > > > > > address: localhost:9999 > > > > > > 2020-06-10 15:20:10.996 DEBUG 29616 --- [ClientTCPWorker] > > > > > > o.a.camel.component.netty.NettyProducer : Channel: [id: > 0x4fd36b4a, > > > > > > L:/127.0.0.1:63714 - R:localhost/127.0.0.1:9999] writing body: > [...] > > > > > > 2020-06-10 15:20:11.000 TRACE 29616 --- [ClientTCPWorker] > > > > > > o.a.camel.component.netty.NettyProducer : Channel open: [id: > > > > > > 0x4fd36b4a, L:/127.0.0.1:63714 - R:localhost/127.0.0.1:9999] > > > > > > 2020-06-10 15:20:11.252 TRACE 29616 --- [ClientTCPWorker] > > > > > > o.a.camel.component.netty.NettyProducer : Operation complete > > > > > > DefaultChannelPromise@1f64970(success) > > > > > > 2020-06-10 15:20:11.256 TRACE 29616 --- [ClientTCPWorker] > > > > > > o.a.camel.component.netty.NettyProducer : Message received: [ > ... ] > > > > > > 2020-06-10 15:20:11.256 DEBUG 29616 --- [ClientTCPWorker] > > > > > > o.a.camel.component.netty.NettyProducer : Channel: [id: > 0x4fd36b4a, > > > > > > L:/127.0.0.1:63714 - R:localhost/127.0.0.1:9999] received body: > > > [...] > > > > > > 2020-06-10 15:20:11.256 TRACE 29616 --- [ClientTCPWorker] > > > > > > o.a.camel.component.netty.NettyProducer : Putting channel back > to > > > > > > pool [id: 0x4fd36b4a, L:/127.0.0.1:63714 - R:localhost/ > > > 127.0.0.1:9999] > > > > > > 2020-06-10 15:20:11.256 TRACE 29616 --- [ClientTCPWorker] > > > > > > o.a.camel.component.netty.NettyProducer : passivateObject > channel > > > > > > request: AbstractBootstrap$PendingRegistrationPromise@347574 > > > (success) > > > > > > > > > > > > 2020-06-10 15:20:21.260 TRACE 29616 --- [ClientTCPWorker] > > > > > > o.a.camel.component.netty.NettyProducer : Exception caught at > > > > > > Channel: [id: 0x4fd36b4a, L:/127.0.0.1:63714 - > > > > > > R:localhost/127.0.0.1:9999] > > > > > > > > > > > > io.netty.handler.timeout.ReadTimeoutException: null > > > > > > > > > > > > 2020-06-10 15:20:21.260 DEBUG 29616 --- [ClientTCPWorker] > > > > > > o.a.camel.component.netty.NettyProducer : Closing channel as an > > > > > > exception was thrown from Netty > > > > > > > > > > > > io.netty.handler.timeout.ReadTimeoutException: null > > > > > > > > > > > > 2020-06-10 15:20:21.261 TRACE 29616 --- [ClientTCPWorker] > > > > > > o.a.camel.component.netty.NettyHelper : Channel closed: [id: > > > > > > 0x4fd36b4a, L:/127.0.0.1:63714 ! R:localhost/127.0.0.1:9999] > > > > > > 2020-06-10 15:20:21.261 TRACE 29616 --- [ClientTCPWorker] > > > > > > o.a.camel.component.netty.NettyProducer : Invalidating channel > from > > > > > > pool [id: 0x4fd36b4a, L:/127.0.0.1:63714 ! R:localhost/ > > > 127.0.0.1:9999] > > > > > > 2020-06-10 15:20:21.261 TRACE 29616 --- [ClientTCPWorker] > > > > > > o.a.camel.component.netty.NettyProducer : Destroying channel > > > request: > > > > > > AbstractBootstrap$PendingRegistrationPromise@347574(success) > > > > > > 2020-06-10 15:20:21.261 WARN 29616 --- [ClientTCPWorker] > > > > > > o.a.c.p.e.RedeliveryErrorHandler : Cannot determine > current > > > > > > route from Exchange with id: ID-WPU8L0058708-1591795167006-0-2, > will > > > > > > fallback and use first error handler. > > > > > > 2020-06-10 15:20:21.261 TRACE 29616 --- [ClientTCPWorker] > > > > > > o.a.camel.component.netty.NettyProducer : Channel closed: [id: > > > > > > 0x4fd36b4a, L:/127.0.0.1:63714 ! R:localhost/127.0.0.1:9999] > > > > > > ``` > > > > > > > > > > > > > > > > > > This seems like a bug to me, but I wanted to send an email first > to > > > > > > fetch your feedback. > > > > > > > > > > > > Thanks in advance for your support. > > > > > > > > > > > > Kind Regards, > > > > > > Vincenzo Galluccio > > > > > > > > > > > > > > > > > > > > -- > > > > > Claus Ibsen > > > > > ----------------- > > > > > http://davsclaus.com @davsclaus > > > > > Camel in Action 2: https://www.manning.com/ibsen2 > > > > > > > > > > > > > > > > > > > > > > -- > > > Claus Ibsen > > > ----------------- > > > http://davsclaus.com @davsclaus > > > Camel in Action 2: https://www.manning.com/ibsen2 > > > > > > > > > > -- > Claus Ibsen > ----------------- > http://davsclaus.com @davsclaus > Camel in Action 2: https://www.manning.com/ibsen2 > >
