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