I'm using Web-flux/Reactive and Webclient, running it on Tomcat and spring-boot.
Everything works fine. I read a lot about it. The problem seems to be that whenever you use Webclient, you have to return or use the response, otherwise it will close the connection and you didn't consume it yet, and you will see a lot of log messages saying that the connection close prematurely, if I had a scenario where a 404 status code is an error I could just use OnStatus and throw an exception, but my scenario is: when the upstream service returns a 404, I have to return manually a mono empty. So I don't use the response from Webclient request, I just use ClientResponse from .exchange() to check the status and handle it. My initial problem is the log messages, because it's just "garbage", you don't want see a lot of it on your log messages. I've read somewhere that if it happens the connection can't be re-used as well, so it sounds really bad, but I don't know... and I just have this message when it's not found, if the response is 200 it returns the object and log messages is not printed.
I tried to use clientResponse.BodyToMono(Void.Class) but it doesn't work either. The log messages keeping appearing.
@Bean
public WebClient webClient(
@Value("${http.client.connection-timeout-millis}") final int connectionTimeoutMillis,
@Value("${http.client.socket-timeout-millis}") final int socketTimeoutMillis,
@Value("${http.client.wire-tap-enabled}") final boolean wireTapEnabled,
final ObjectMapper objectMapper) {
Consumer<Connection> doOnConnectedConsumer = connection ->
connection
.addHandler(new ReadTimeoutHandler(socketTimeoutMillis, MILLISECONDS))
.addHandler(new WriteTimeoutHandler(connectionTimeoutMillis, MILLISECONDS));
TcpClient tcpClient = TcpClient.newConnection()
.wiretap(wireTapEnabled)
.option(CONNECT_TIMEOUT_MILLIS, connectionTimeoutMillis)
.doOnConnected(doOnConnectedConsumer);
return WebClient.builder()
.clientConnector(new ReactorClientHttpConnector(HttpClient.from(tcpClient).compress(true)))
.exchangeStrategies(customExchangeStrategies(objectMapper))
.build();
}
// ..........
MultiValueMap<String, String> params = getParams(t1, t2);
return webClient.get()
.uri(HttpUtils.buildUrl(serviceUrl, params, name))
.exchange()
.flatMap(this::handleClientResponse)
.onErrorMap(Exception.class, ex -> handleUnexpectedEx(ex, name, params));
}
log entries
2019-07-08 11:56:51.972 WARN [-,,,] 1504 --- [ctor-http-nio-3] reactor.netty.channel.FluxReceive : [id: 0x66c8568c, L:/127.0.0.1:62319 ! R:localhost/127.0.0.1:8990] An exception has been observed post termination
reactor.netty.http.client.PrematureCloseException: Connection prematurely closed DURING response
2019-07-08 11:56:52.013 DEBUG [-,,,] 1504 --- [ctor-http-nio-2] reactor.netty.ReactorNetty : [id: 0xf50bdf8d, L:/127.0.0.1:62324 ! R:localhost/127.0.0.1:8990] Non Removed handler: ReadTimeoutHandler, context: ChannelHandlerContext(ReadTimeoutHandler, [id: 0xf50bdf8d, L:/127.0.0.1:62324 ! R:localhost/127.0.0.1:8990]), pipeline: DefaultChannelPipeline{(reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.left.decompressor = io.netty.handler.codec.http.HttpContentDecompressor), (WriteTimeoutHandler = io.netty.handler.timeout.WriteTimeoutHandler), (ReadTimeoutHandler = io.netty.handler.timeout.ReadTimeoutHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2019-07-08 11:56:52.014 DEBUG [-,,,] 1504 --- [ctor-http-nio-2] reactor.netty.ReactorNetty : [id: 0xf50bdf8d, L:/127.0.0.1:62324 ! R:localhost/127.0.0.1:8990] Non Removed handler: WriteTimeoutHandler, context: ChannelHandlerContext(WriteTimeoutHandler, [id: 0xf50bdf8d, L:/127.0.0.1:62324 ! R:localhost/127.0.0.1:8990]), pipeline: DefaultChannelPipeline{(reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.left.decompressor = io.netty.handler.codec.http.HttpContentDecompressor), (WriteTimeoutHandler = io.netty.handler.timeout.WriteTimeoutHandler), (ReadTimeoutHandler = io.netty.handler.timeout.ReadTimeoutHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2019-07-08 11:56:52.014 DEBUG [-,,,] 1504 --- [ctor-http-nio-2] r.netty.resources.NewConnectionProvider : [id: 0xf50bdf8d, L:/127.0.0.1:62324 ! R:localhost/127.0.0.1:8990] onStateChange([response_incomplete], GET{uri=/service/TWFDHF?T1=1.0.0&T2=1, connection=SimpleConnection{channel=[id: 0xf50bdf8d, L:/127.0.0.1:62324 ! R:localhost/127.0.0.1:8990]}})
2019-07-08 11:56:52.014 WARN [-,,,] 1504 --- [ctor-http-nio-2] reactor.netty.channel.FluxReceive : [id: 0xf50bdf8d, L:/127.0.0.1:62324 ! R:localhost/127.0.0.1:8990] An exception has been observed post termination
log entries with wiretap enabled
2019-07-10 14:51:19.295 DEBUG [-,,,] 2940 --- [ctor-http-nio-2] reactor.netty.tcp.TcpClient : [id: 0x677da0d4, L:/127.0.0.1:62385 ! R:localhost/127.0.0.1:8990] UNREGISTERED
2019-07-10 14:51:19.541 DEBUG [-,,,] 2940 --- [ctor-http-nio-4] reactor.netty.tcp.TcpClient : [id: 0xa7f41d1e, L:/127.0.0.1:62384 - R:localhost/127.0.0.1:8990] CLOSE
2019-07-10 14:51:19.542 DEBUG [-,,,] 2940 --- [ctor-http-nio-4] r.n.resources.PooledConnectionProvider : [id: 0xa7f41d1e, L:/127.0.0.1:62384 ! R:localhost/127.0.0.1:8990] Channel cleaned, now 0 active connections and 9 inactive connections
2019-07-10 14:51:19.542 DEBUG [-,,,] 2940 --- [ctor-http-nio-4] r.n.resources.PooledConnectionProvider : [id: 0xa7f41d1e, L:/127.0.0.1:62384 ! R:localhost/127.0.0.1:8990] Channel closed, now 0 active connections and 8 inactive connections
2019-07-10 14:51:19.542 DEBUG [-,,,] 2940 --- [ctor-http-nio-4] reactor.netty.ReactorNetty : [id: 0xa7f41d1e, L:/127.0.0.1:62384 ! R:localhost/127.0.0.1:8990] Non Removed handler: ReadTimeoutHandler, context: ChannelHandlerContext(ReadTimeoutHandler, [id: 0xa7f41d1e, L:/127.0.0.1:62384 ! R:localhost/127.0.0.1:8990]), pipeline: DefaultChannelPipeline{(reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (WriteTimeoutHandler = io.netty.handler.timeout.WriteTimeoutHandler), (ReadTimeoutHandler = io.netty.handler.timeout.ReadTimeoutHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2019-07-10 14:51:19.543 DEBUG [-,,,] 2940 --- [ctor-http-nio-4] reactor.netty.ReactorNetty : [id: 0xa7f41d1e, L:/127.0.0.1:62384 ! R:localhost/127.0.0.1:8990] Non Removed handler: WriteTimeoutHandler, context: ChannelHandlerContext(WriteTimeoutHandler, [id: 0xa7f41d1e, L:/127.0.0.1:62384 ! R:localhost/127.0.0.1:8990]), pipeline: DefaultChannelPipeline{(reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (WriteTimeoutHandler = io.netty.handler.timeout.WriteTimeoutHandler), (ReadTimeoutHandler = io.netty.handler.timeout.ReadTimeoutHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2019-07-10 14:51:19.543 DEBUG [-,,,] 2940 --- [ctor-http-nio-4] reactor.netty.tcp.TcpClient : [id: 0xa7f41d1e, L:/127.0.0.1:62384 ! R:localhost/127.0.0.1:8990] INACTIVE
2019-07-10 14:51:19.544 DEBUG [-,,,] 2940 --- [ctor-http-nio-4] r.n.resources.PooledConnectionProvider : [id: 0xa7f41d1e, L:/127.0.0.1:62384 ! R:localhost/127.0.0.1:8990] onStateChange(GET{uri=/dataviews/TWN_EMPLBENINFO_FIXED?version=1.0.0&sequence=1, connection=PooledConnection{channel=[id: 0xa7f41d1e, L:/127.0.0.1:62384 ! R:localhost/127.0.0.1:8990]}}, [response_incomplete])
2019-07-10 14:51:19.544 WARN [-,,,] 2940 --- [ctor-http-nio-4] reactor.netty.channel.FluxReceive : [id: 0xa7f41d1e, L:/127.0.0.1:62384 ! R:localhost/127.0.0.1:8990] An exception has been observed post termination
and my handler
protected Mono handleClientResponseError(final ClientResponse clientResponse) {
clientResponse.bodyToMono(Void.class);
Mono<ErrorResponse> errorResponse = clientResponse.body(BodyExtractors.toMono(ErrorResponse.class));
return errorResponse.flatMap(err -> {
log.debug("Received HttpStatusCodeException when calling {} Registry: {}", getGatewayName(),
err.getErrorEnvelope().getMessage());
return Mono.error(new UpStreamServiceHttpException(err, clientResponse.rawStatusCode()));
}).switchIfEmpty(Mono.error(() -> {
log.debug("Received HttpStatusCodeException when calling {} Registry: {}", getGatewayName());
return new UpStreamServiceHttpException("Bad Gateway", clientResponse.rawStatusCode());
}));
}
I tried using clientResponse.bodyToMono(Void.class); to complete the response, but it still doesn't work, I need a way to finish the response from Webclient, and then be able to re-use the connection pool and get rid of those log messages.
I've created an issue on Github, but it was closed, so I'm creating this question here. https://github.com/spring-projects/spring-framework/issues/23249
I finally found a way to finish the response and I will share it here for anyone who comes across this problem
before I had this:
private Mono<Optional<JsonNode>> handleHttpErrorStatus(final ClientResponse clientResponse) {
if (clientResponse.statusCode().equals(HttpStatus.NOT_FOUND)) {
clientResponse.bodyToMono(Void.class);
return Mono.just(Optional.empty());
} else {
return handleClientResponseError(clientResponse);
}
}
But it didn't work, apparently, because I wasn't returning it anyway, so after digging I tried this:
private Mono<Optional<JsonNode>> handleHttpErrorStatus(final ClientResponse clientResponse) {
if (clientResponse.statusCode().equals(HttpStatus.NOT_FOUND)) {
return clientResponse.bodyToMono(Void.class).thenReturn((Optional.empty()));
} else {
return handleClientResponseError(clientResponse);
}
}
and it works fine, I checked the wiretap logs and everything looks fine now.
2019-07-10 16:44:39.096 DEBUG [-,,,] 16260 --- [ctor-http-nio-2] r.n.http.client.HttpClientOperations : [id: 0x461d8170, L:/127.0.0.1:64298 - R:localhost/127.0.0.1:8990] Received response (auto-read:false) : [Content-Type=application/json;charset=UTF-8, Transfer-Encoding=chunked, Date=Wed, 10 Jul 2019 15:44:38 GMT]
2019-07-10 16:44:39.096 DEBUG [-,,,] 16260 --- [ctor-http-nio-2] r.n.resources.PooledConnectionProvider : [id: 0x461d8170, L:/127.0.0.1:64298 - R:localhost/127.0.0.1:8990] onStateChange(GET{uri=/dataviews/TWN_EMPLPIM_AVRO?version=1.0.0&sequence=1, connection=PooledConnection{channel=[id: 0x461d8170, L:/127.0.0.1:64298 - R:localhost/127.0.0.1:8990]}}, [response_received])
2019-07-10 16:44:39.098 DEBUG [-,bdd6433efa276f10,bdd6433efa276f10,false] 16260 --- [ctor-http-nio-2] reactor.netty.channel.FluxReceive : [id: 0x461d8170, L:/127.0.0.1:64298 - R:localhost/127.0.0.1:8990] Subscribing inbound receiver [pending: 0, cancelled:false, inboundDone: false]
2019-07-10 16:44:39.099 DEBUG [-,bdd6433efa276f10,bdd6433efa276f10,false] 16260 --- [ctor-http-nio-2] reactor.netty.tcp.TcpClient : [id: 0x461d8170, L:/127.0.0.1:64298 - R:localhost/127.0.0.1:8990] CLOSE
2019-07-10 16:44:39.099 DEBUG [-,bdd6433efa276f10,bdd6433efa276f10,false] 16260 --- [ctor-http-nio-2] r.n.resources.PooledConnectionProvider : [id: 0x461d8170, L:/127.0.0.1:64298 ! R:localhost/127.0.0.1:8990] Channel cleaned, now 1 active connections and 1 inactive connections
2019-07-10 16:44:39.099 DEBUG [-,bdd6433efa276f10,bdd6433efa276f10,false] 16260 --- [ctor-http-nio-2] r.n.resources.PooledConnectionProvider : [id: 0x461d8170, L:/127.0.0.1:64298 ! R:localhost/127.0.0.1:8990] Channel closed, now 1 active connections and 0 inactive connections
2019-07-10 16:44:39.099 DEBUG [-,bdd6433efa276f10,bdd6433efa276f10,false] 16260 --- [ctor-http-nio-2] reactor.netty.ReactorNetty : [id: 0x461d8170, L:/127.0.0.1:64298 ! R:localhost/127.0.0.1:8990] Non Removed handler: ReadTimeoutHandler, context: ChannelHandlerContext(ReadTimeoutHandler, [id: 0x461d8170, L:/127.0.0.1:64298 ! R:localhost/127.0.0.1:8990]), pipeline: DefaultChannelPipeline{(reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (WriteTimeoutHandler = io.netty.handler.timeout.WriteTimeoutHandler), (ReadTimeoutHandler = io.netty.handler.timeout.ReadTimeoutHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2019-07-10 16:44:39.099 DEBUG [-,bdd6433efa276f10,bdd6433efa276f10,false] 16260 --- [ctor-http-nio-2] reactor.netty.ReactorNetty : [id: 0x461d8170, L:/127.0.0.1:64298 ! R:localhost/127.0.0.1:8990] Non Removed handler: WriteTimeoutHandler, context: ChannelHandlerContext(WriteTimeoutHandler, [id: 0x461d8170, L:/127.0.0.1:64298 ! R:localhost/127.0.0.1:8990]), pipeline: DefaultChannelPipeline{(reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (WriteTimeoutHandler = io.netty.handler.timeout.WriteTimeoutHandler), (ReadTimeoutHandler = io.netty.handler.timeout.ReadTimeoutHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2019-07-10 16:44:39.100 DEBUG [-,,,] 16260 --- [ctor-http-nio-2] reactor.netty.tcp.TcpClient : [id: 0x461d8170, L:/127.0.0.1:64298 ! R:localhost/127.0.0.1:8990] READ COMPLETE
2019-07-10 16:44:39.102 DEBUG [-,,,] 16260 --- [ctor-http-nio-2] reactor.netty.tcp.TcpClient : [id: 0x461d8170, L:/127.0.0.1:64298 ! R:localhost/127.0.0.1:8990] INACTIVE
2019-07-10 16:44:39.102 DEBUG [-,,,] 16260 --- [ctor-http-nio-2] reactor.netty.tcp.TcpClient : [id: 0x461d8170, L:/127.0.0.1:64298 ! R:localhost/127.0.0.1:8990] UNREGISTERED
2019-07-10 16:44:39.122 DEBUG [-,,,] 16260 --- [ctor-http-nio-2] reactor.netty.tcp.TcpClient : [id: 0xbe2cb147, L:/127.0.0.1:64295 - R:localhost/127.0.0.1:8990] READ: 398B