☰

PrematureCloseException: 接続が途中で閉じられました 質問する

tag-icon • tag-icon spring netty spring-webflux reactive spring-webclient
PrematureCloseException: 接続が途中で閉じられました 質問する

私は Web-flux/Reactive と Webclient を使用しており、Tomcat と spring-boot で実行しています。

すべて正常に動作します。これについてはたくさん読みました。問題は、Webclient を使用するたびに、応答を返すか使用する必要があることのようです。そうしないと、接続が閉じられ、まだ使用されていないため、 というログ メッセージが多数表示されます。404the connection close prematurelyステータス コードがエラーであるシナリオでは、 を使用すればOnStatus例外をスローできますが、私のシナリオでは、アップストリーム サービスが 404 を返すと、手動で mono 空を返す必要があります。そのため、Webclient 要求からの応答は使用せず、ClientResponseから.exchange()ステータスをチェックして処理するだけです。最初の問題はログ メッセージです。これは単なる「ゴミ」であるため、ログ メッセージに多く表示されるのは望ましくありません。これが発生すると接続も再利用できないとどこかで読んだことがあります。これは本当にひどいように思えますが、わかりません... 見つからないときにこのメッセージが表示されるだけです。応答が 200 の場合は、オブジェクトが返され、ログ メッセージは印刷されません。

使用してみましたclientResponse.BodyToMono(Void.Class)が、動作しません。ログ メッセージが引き続き表示されます。

 @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));
  }

ログエントリ

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

盗聴が有効になっているログエントリ

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

そして私のハンドラー

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());
    }));
  }

応答を完了するためにを使用しようとしましたclientResponse.bodyToMono(Void.class);が、まだ機能しません。Webclient からの応答を完了し、接続プールを再利用してそれらのログ メッセージを取り除く方法が必要です。

Github で問題を作成しましたが、解決されなかったため、ここで質問を作成します。https://github.com/spring-projects/spring-framework/issues/23249

ベストアンサー1

ようやく回答を完了する方法を見つけたので、この問題に遭遇した人のためにここで共有します。

これを手に入れる前は:

 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);
    }
  }

しかし、どうやらそれは機能しなかったようです。どうせ返品するつもりはなかったので、調べてみたところ、次のことを試しました。

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);
    }
  }

正常に動作しています。盗聴ログを確認しましたが、すべて正常に動作しています。

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

おすすめ記事