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
