You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@camel.apache.org by Vincenzo Galluccio <vi...@gmail.com> on 2020/06/10 13:37:52 UTC
Camel netty requestTimeout doesn't work properly
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
Re: Camel netty requestTimeout doesn't work properly
Posted by Zheng Feng <zf...@redhat.com>.
It seems that we can use the NettyRequestTimeoutIussueTest to reproduer
this issue. But it needs to be run manually and I have checked it with the
master branch and there is a failure in the camel-netty-test.log
I sent the PR [2] with my proposal to fix this issue.
[1]
https://github.com/apache/camel/blob/master/components/camel-netty/src/test/java/org/apache/camel/component/netty/NettyRequestTimeoutIssueTest.java
[2] https://github.com/apache/camel/pull/3925
On Tue, Jun 16, 2020 at 5:32 PM Zheng Feng <zf...@redhat.com> wrote:
> 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 <cl...@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 <cl...@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 <cl...@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
>> > > > > <vi...@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
>>
>>
Re: Camel netty requestTimeout doesn't work properly
Posted by Zheng Feng <zf...@redhat.com>.
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 <cl...@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 <cl...@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 <cl...@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
> > > > > <vi...@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
>
>
Re: Camel netty requestTimeout doesn't work properly
Posted by Claus Ibsen <cl...@gmail.com>.
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 <cl...@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 <cl...@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
> > > > <vi...@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
Re: Camel netty requestTimeout doesn't work properly
Posted by Zheng Feng <zf...@redhat.com>.
Feel free to assign the issue to me and I can take a look at it.
On Mon, Jun 15, 2020 at 5:22 PM Claus Ibsen <cl...@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 <cl...@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
> > > <vi...@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
>
>
Re: Camel netty requestTimeout doesn't work properly
Posted by Claus Ibsen <cl...@gmail.com>.
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 <cl...@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
> > <vi...@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
Re: Camel netty requestTimeout doesn't work properly
Posted by Zheng Feng <zf...@redhat.com>.
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 <cl...@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
> <vi...@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
>
>
Re: Camel netty requestTimeout doesn't work properly
Posted by Claus Ibsen <cl...@gmail.com>.
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
<vi...@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