WebClient 에서 raw response body 로깅

모니터링 부서에서 특정 webClient api 요청과 응답 로그를 찍어주길 희망했다. 해당 webClient 는 retrieve 를 사용하고 있었기 때문에 doOnSuccess 와 onErrorMap 에 성공/실패 로그를 남겼다.

 

cf) 응답 response body 는 xml 로 전달해주는 api 다.

this.webClient.get()
  .uri(uri)
  .retrieve()
  .bodyToMono(YbsResponse.class)
  .doOnSuccess(ybsResponse -> {
    log.info(시간, uri, ybsResponse, 성공메세지)
  })
  .onErrorMap(throwable -> {
    log.info(시간, uri, throwable.getMessage(), 실패메세지)
  })
  ... // 생략
  

@XmlRootElement(name = "infos")
@ToString
@Getter
@Setter
public class YbsResponse {

  @XmlElement(name = "info")
  private List<Ybs> infoList;
  
  @ToString
  @Getter
  @Setter
  public static class Ybs {
    private String name;
    private int age;
  }
}

 

그런데 모니터링 부서에서 response status code 와 content type 정보는 꼭 필요하다고 연락이 왔다. 하지만 문제가 있다. retrieve 를 이용해서는 response status code 와 content type 정보를 남길 수 없다. onStatus 를 이용하면 반쪽만 해결되기 때문이다. onStatus 두번째 인자 리턴타입은 exception 클래스만 가능하다. response status 가 성공(2xx)일 때 처리가 불가능하다.

this.webClient.get()
      .uri(uri)
      .retrieve()
      .onStatus(
        httpStatus ->  httpStatus.isError(),
        clientResponse -> {
          log.info("{}", clientResponse.rawStatusCode());
          log.info("{}", clientResponse.headers().contentType().map(MediaType::toString).orElse(""));
          return clientResponse.createException().flatMap(ResponseException::createException);
        }
      )
      .onStatus(
        httpStatus ->  httpStatus.is2xxSuccessful(),
        clientResponse -> {
          log.info("{}", clientResponse.rawStatusCode());
          log.info("{}", clientResponse.headers().contentType().map(MediaType::toString).orElse(""));

          // onStatus 는 반드시 Mono<? extends Throwable>> exceptionFunction 을 리턴해야함
          return ??
        }
      )

 

결국 로그를 위해서 retrieve 대신 exchangeToMono 를 써야했다. 한가지 특이한건 요청 로그도 exchangeToMono 안에서 찍는다는 점이다. 사실 exchangeToMono 에 진입했을 때는 응답을 받은 후라, 정확히 요청을 보냈을 타이밍이랑 맞지 않다. 

Instant requestTime = Instant.now();
this.webClient.get()
      .uri(uri)
      .exchangeToMono(clientResponse -> {
        // 요청 로그
        log.info(requestTime, uri);

        Instant responseTime = Instant.now();
        if (clientResponse.statusCode().isError()) {
          return clientResponse.createException()
            .doOnSuccess(
              exception -> log.info( // 응답 로그
                responseTime, 
                clientResponse.rawStatusCode(),
                clientResponse.headers().contentType().map(MediaType::toString).orElse(""),
                exception.getResponseBodyAsString(StandardCharsets.UTF_8)
              ))
            .flatMap(ResponseException::createException);
        }

        return clientResponse.bodyToMono(YbsResponse.class)
          .doOnSuccess(body -> log.info( // 응답 로그
              responseTime,
              clientResponse.rawStatusCode(),
              clientResponse.headers().contentType().map(MediaType::toString).orElse(""),
              body
            )
          ).doOnError(throwable -> log.info( // 응답 로그
              responseTime,
              clientResponse.rawStatusCode(),
              clientResponse.headers().contentType().map(MediaType::toString).orElse(""),
              "doOnError"
            ))
          );

 

따지고보면 ExchangeFilterFunction.ofRequestProcessor 를 이용해 요청 로그를 찍는게 더 적합하다. 하지만 그렇게 하지 않은 이유는 response 시점에 사용하는 ExchangeFilterFunction.ofResponseProcessor 때문이었다. ofResponseProcessor 를 이용해 응답 로그를 찍는게 불편해서 webClient 내부에 통일시켜 로그를 찍었다. 왜 불편했는지는 뒤에서 자세히 설명하겠다.

 

webClientBuilder
  .defaultHeaders(생략)
  .clientConnector(생략)
  .filter(ExchangeFilterFunction.ofRequestProcessor(clientRequest -> {
    log.info(Instant.now(), clientRequest.url());
    return Mono.just(clientRequest);
  })
  ... 생략

 

exchangeToMono 방식으로 수정해서 response status code 와 content type 정보가 로그로 잘 찍히는것을 확인했다. 그런데 모니터링부서에서 또다른 요청이 왔다. response body 를 YbsResponse 객체로 찍지 말고 raw response body 인 xml 형태로 찍어달라는 것이다.

return clientResponse.bodyToMono(YbsResponse.class)
          .doOnSuccess(body -> log.info(
              responseTime,
              clientResponse.rawStatusCode(),
              clientResponse.headers().contentType().map(MediaType::toString).orElse(""),
              body
            )

/////////

@XmlRootElement(name = "infos")
@ToString
@Getter
@Setter
public class YbsResponse {

  @XmlElement(name = "info")
  private List<Ybs> infoList;
  
  @ToString
  @Getter
  @Setter
  public static class Ybs {
    private String name;
    private int age;
  }
}

 

이 요구사항을 만족시키려면 bodyToMono 로 YbsResponse 타입 변환을 바로 하면 안된다. 로그를 찍기 위해 String type 으로 먼저 변환하고 String type 의 xml 을 다시 YbsResponse 타입으로 변환시켜야한다. 그래서 아래와 같이 수정했지만 제대로 변환되지 않았다. 

        return clientResponse.bodyToMono(String.class)
          .doOnSuccess(body -> log.info(
              responseTime,
              clientResponse.rawStatusCode(),
              clientResponse.headers().contentType().map(MediaType::toString).orElse(""),
              body
            )
          ).doOnError(throwable -> log.info(
              responseTime,
              clientResponse.rawStatusCode(),
              clientResponse.headers().contentType().map(MediaType::toString).orElse(""),
              "doOnError"
            ))
          ).mapNotNull(body -> {
              try {
                // 문제 있는 코드
                return xmlMapper.readValue(body, YbsResponse.class);
              } catch (Exception ex) {
                throw new RuntimeException(ex);
              }
            }
          );
          
////////

ObjectMapper xmlMapper = Jackson2ObjectMapperBuilder.xml()
  .defaultUseWrapper(false)
  .build();

 

이유를 따져보니 Jackson 을 이용해 만든 xmlMapper 는 YbsResponse 에 있는 @XmlRootElement, @XmlElement 를 제대로 인식하지 못했다. 대신 @JacksonXmlRootElement, @JacksonXmlProperty 로 바꿔주면 제대로 인식한다.

 

그외에도 jackson-module-jaxb-annotations 의존성을 추가하고, JaxbAnnotationModule 을 넣어주는 방법도 있다. 이 방법을 사용하면 YbsResponse 를 수정할 필요없다.

// 1. 추가
api("com.fasterxml.jackson.module:jackson-module-jaxb-annotations")

ObjectMapper xmlMapper = Jackson2ObjectMapperBuilder.xml()
  .defaultUseWrapper(false)
  .modules(new JaxbAnnotationModule()) // 2. 추가
  .build();

 

WebClient 는 기본적으로 xml 을 object 로 변환할 때 jaxb2XmlDecoder 를 사용한다.

 

ExchangeStrategies 를 따로 안만들고 default 로만 쓰면 defaultCodecs 의 jaxb2Decoder 가 null 인것을 알 수 있다.

 

로그를 위해 String 으로 있는 xml 을 다시 YbsResponse 로 변환할때, 기존처럼 jaxb2XmlDecoder 를 사용하는게 더 적합하다고 판단해서 다시 수정했다.

        return clientResponse.bodyToMono(String.class)
          .doOnSuccess(body -> log.info(
              responseTime,
              clientResponse.rawStatusCode(),
              clientResponse.headers().contentType().map(MediaType::toString).orElse(""),
              body
            )
          ).doOnError(throwable -> log.info(
              responseTime,
              clientResponse.rawStatusCode(),
              clientResponse.headers().contentType().map(MediaType::toString).orElse(""),
              "doOnError"
            ))
          ).mapNotNull(body -> {
              try {
                // dataBufferFactory 와 jaxb2XmlDecoder 는 외부에서 생성해서 주입받음
                DataBuffer dataBuffer = dataBufferFactory.wrap(body.getBytes(StandardCharsets.UTF_8));
                ResolvableType resolvableType = ResolvableType.forClass(YbsResponse.class);
                
                return (YbsResponse)jaxb2XmlDecoder.decode(dataBuffer, resolvableType, null, null);
              } catch (Exception ex) {
                throw new RuntimeException(ex);
              }
            }
          );

 

마지막으로 왜 ExchangeFilterFunction.ofResponseProcessor 를 이용하지 않았는지 설명하겠다. 로그를 위한 부가작업을 ofResponseProcessor 에서 전담하도록 만드는게 가장 바람직하다고 생각했다. 그런데 ofResponseProcessor 에서 response body 를 String 으로 변환하고 뒤에서 다시 YbsResponse 로 변환하려면 response body stream 소비에 대해 신경을 많이 써줘야 한다(한번밖에 소비할 수 없으므로). 메모리릭이 발생하진 않은지 따져봐야 하는등 복잡해진다. 그래서 webClient 에서 요청로그, 응답로그 모두 찍기로 했다.

webClientBuilder
  .defaultHeaders(생략)
  .clientConnector(생략)
  .filter(ExchangeFilterFunction.ofRequestProcessor(clientRequest -> { 생략 }))
  .filter(ExchangeFilterFunction.ofResponseProcessor(clientResponse -> {
      if (clientResponse.statusCode().isError()) {
        return clientResponse.createException()
          .doOnSuccess(exception -> log.info(로그 추가))
          .flatMap(ResponseException::createException);
      }

      // 문제 있는 코드
      DataBufferFactory bufferFactory = new DefaultDataBufferFactory();
      Flux<DataBuffer> fluxDataBuffer = clientResponse.bodyToFlux(DataBuffer.class);
      Flux<DataBuffer> sharedFluxDataBuffer = fluxDataBuffer.map(dataBuffer ->
      bufferFactory.wrap(
        Arrays.copyOfRange(dataBuffer.asByteBuffer().array(),
        dataBuffer.readPosition(), dataBuffer.writePosition()))).share();

      return clientResponse.bodyToMono(String.class)
        .doOnSuccess(body -> log.info(로그 추가))
        .doOnError(throwable -> log.info(로그 추가))
        // response body stream 은 한번밖에 소비할 수 없으므로 복사본을 넘김
        .map(it -> ClientResponse.from(clientResponse).body(sharedFluxDataBuffer).build());
      }))
      .build();