RestTemplate 응답 log 확인하기

Spring framework 5.1.6.RELEASE 기준으로 작성함

RestTemplate log 보기

RestTemplate의 응답을 확인하고자 하는 경우 아래처럼 로그를 추가하면 된다.

logging.level.org.springframework.web.client=DEBUG

이 경우 body정보를 log로 남기게 되는데 다만 전제 조건이 있다.

RestTemplate은 callback을 2가지 유형으로 처리를 한다.

RequestCallback	설명
AcceptHeaderRequestCallback	AcceptHeader를 만드는 Callback
HttpEntityRequestCallback	RequestBody를 만드는 Callback AcceptHeaderRequestCallback을 확장하여 구현됨

getForObject나 getForEntity의 경우 요청에 body가 없기 대문에 AcceptHeaderRequestCallback을 사용하고 acceptHeader 정보를 로그로 남기게 된다.

그외의 post, put 는 요청 시 body에 데이터를 담아 넘기기 때문에 HttpEntityRequestCallback을 사용하고 요청에 사용된 requestBody 정보를 로그로 남기게 된다. (또한 AcceptHeaderRequestCallback을 확장하여 구현되었으므로 acceptHeader 정보도 같이 로그에 남긴다.

하지만 응답에 대한 로그는 RestTemplate에서는 status나 code 정보만 아래처럼 간략하게 남긴다.

// 성공인 경우
2019-06-19T14:47:28.417+09:00 DEBUG 24188 --- [nt-operations-1] o.s.web.client.RestTemplate              : Response 200 OK

// 실패인 경우
2019-06-19T14:47:26.637+09:00 DEBUG 24188 --- [strix-session-1] o.s.web.client.RestTemplate              : Response 500 INTERNAL_SERVER_ERROR

response data 를 보고 싶은 경우 위 debug 설정으로는 확인할 수 없다.

restTemplate 생성 시 clientHttpRequestFactory를 지정할 수 있는데 현재는 아래처럼 지원하고 있다.

ClientHttpRequestFactory

HttpComponents log 보기

만약 apacheApache HttpComponents의 HttpComponentsClientHttpRequestFactory를 다음처럼 선언하여 사용하고 있다면

@ConditionalOnMissingBean(RestTemplate.class)
@Bean
public RestTemplate restTemplate(RestTemplateBuilder restTemplateBuilder) {
    return restTemplateBuilder.build();
}

@Bean
public RestTemplateCustomizer restTemplateCustomizer() {
    return (restTemplate) -> restTemplate.setRequestFactory(clientHttpRequestFactory()); 
}

@Bean
@ConditionalOnMissingBean(ClientHttpRequestFactory.class)
public ClientHttpRequestFactory clientHttpRequestFactory() {
    HttpComponentsClientHttpRequestFactory clientHttpRequestFactory = new HttpComponentsClientHttpRequestFactory();
    clientHttpRequestFactory.setConnectTimeout(3000);
    clientHttpRequestFactory.setReadTimeout(3000);
    return clientHttpRequestFactory;
}

아래처럼 로그를 추가해주면

logging.level.org.apache.http=DEBUG

아래처럼 로그가 남게 된다.

2019-06-19T14:47:28.401+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.headers                  : http-outgoing-1 >> GET /요청주소
2019-06-19T14:47:28.401+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.headers                  : http-outgoing-1 >> Accept: application/json, application/*+json
2019-06-19T14:47:28.401+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.headers                  : http-outgoing-1 >> Content-Type: application/json
2019-06-19T14:47:28.401+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.headers                  : http-outgoing-1 >> Authorization: 헤더정보
2019-06-19T14:47:28.402+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.headers                  : http-outgoing-1 >> Host: 호스트정보
2019-06-19T14:47:28.402+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.headers                  : http-outgoing-1 >> Connection: Keep-Alive
2019-06-19T14:47:28.402+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.headers                  : http-outgoing-1 >> User-Agent: Apache-HttpClient/4.5.8 (Java/11.0.2)
2019-06-19T14:47:28.402+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.headers                  : http-outgoing-1 >> Accept-Encoding: gzip,deflate
2019-06-19T14:47:28.402+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.wire                     : http-outgoing-1 >> "GET /요청주소 HTTP/1.1[\r][\n]"
2019-06-19T14:47:28.402+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.wire                     : http-outgoing-1 >> "Accept: application/json, application/*+json[\r][\n]"
2019-06-19T14:47:28.402+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.wire                     : http-outgoing-1 >> "Content-Type: application/json[\r][\n]"
2019-06-19T14:47:28.402+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.wire                     : http-outgoing-1 >> "Authorization: 헤더정보[\r][\n]"
2019-06-19T14:47:28.403+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.wire                     : http-outgoing-1 >> "Host: 호스트정보[\r][\n]"
2019-06-19T14:47:28.403+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.wire                     : http-outgoing-1 >> "Connection: Keep-Alive[\r][\n]"
2019-06-19T14:47:28.403+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.wire                     : http-outgoing-1 >> "User-Agent: Apache-HttpClient/4.5.8 (Java/11.0.2)[\r][\n]"
2019-06-19T14:47:28.403+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.wire                     : http-outgoing-1 >> "Accept-Encoding: gzip,deflate[\r][\n]"
2019-06-19T14:47:28.403+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.wire                     : http-outgoing-1 >> "[\r][\n]"
2019-06-19T14:47:28.414+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.wire                     : http-outgoing-1 << "HTTP/1.1 200 OK[\r][\n]"
2019-06-19T14:47:28.415+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.wire                     : http-outgoing-1 << "Content-Type: application/json[\r][\n]"
2019-06-19T14:47:28.415+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.wire                     : http-outgoing-1 << "Date: Wed, 19 Jun 2019 05:47:28 GMT[\r][\n]"
2019-06-19T14:47:28.415+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.wire                     : http-outgoing-1 << "Content-Length: 144[\r][\n]"
2019-06-19T14:47:28.415+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.wire                     : http-outgoing-1 << "Server: 서버정보[\r][\n]"
2019-06-19T14:47:28.415+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.wire                     : http-outgoing-1 << "[\r][\n]"
2019-06-19T14:47:28.415+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.wire                     : http-outgoing-1 << "응답데이터"
2019-06-19T14:47:28.415+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.headers                  : http-outgoing-1 << HTTP/1.1 200 OK
2019-06-19T14:47:28.416+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.headers                  : http-outgoing-1 << Content-Type: application/json
2019-06-19T14:47:28.416+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.headers                  : http-outgoing-1 << Date: Wed, 19 Jun 2019 05:47:28 GMT
2019-06-19T14:47:28.416+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.headers                  : http-outgoing-1 << Content-Length: 144
2019-06-19T14:47:28.416+09:00 DEBUG 24188 --- [nt-operations-1] org.apache.http.headers                  : http-outgoing-1 << Server: AppGate2/5995702.63 Instance/1.580356182

org.apache.http.headers는 요청과 응답의 header정보를 간략하게 남기고 org.apache.http.wire는 header정보와 응답 결과까지 남긴다.

따라서 적절히 보고 싶은 로그만 설정하면 된다.

okhttp3 log 보기

만약 okhttp3 를 clientHttpRequestFactory로 사용하고 있다면 httpComponents처럼 로그 설정만으로는 로그가 출력되지 않는다.

okhttp3 의 요청 처리 코드에 로그 처리가 없기 때문이며 로그를 추가하기 위해선 logging-interceptor dependency를 추가한 후 HttpLoggingInterceptor를 OkHttpClient에 추가해주어야 한다.

<dependency>
    <groupId>com.squareup.okhttp3</groupId>
    <artifactId>okhttp</artifactId>
</dependency>
<dependency>
    <groupId>com.squareup.okhttp3</groupId>
    <artifactId>logging-interceptor</artifactId>
</dependency>

@ConditionalOnMissingBean(RestTemplate.class)
@Bean
public RestTemplate restTemplate(RestTemplateBuilder restTemplateBuilder) {
    return restTemplateBuilder.build();
}

@Bean
public RestTemplateCustomizer restTemplateCustomizer() {
    return (restTemplate) -> restTemplate.setRequestFactory(clientHttpRequestFactory()); 
}

@Bean
@ConditionalOnMissingBean(ClientHttpRequestFactory.class)
public ClientHttpRequestFactory clientHttpRequestFactory() {
    HttpLoggingInterceptor httpLoggingInterceptor = new HttpLoggingInterceptor();
    httpLoggingInterceptor.setLevel(Level.BODY);
    OkHttpClient client = new OkHttpClient.Builder()
            .addInterceptor(httpLoggingInterceptor)
            .build();
    OkHttp3ClientHttpRequestFactory clientHttpRequestFactory = new OkHttp3ClientHttpRequestFactory(client);
    return clientHttpRequestFactory;
}

okhttp3의 Level enum은 NONE, BASIC, HEADERS, BODY가 있다.

이 중 BODY를 설정하면 응답 결과를 다음처럼 확인할 수 있다.

6월 20, 2019 8:14:50 오전 okhttp3.internal.platform.Platform log
정보: --> GET http://요청주소 http/1.1
6월 20, 2019 8:14:50 오전 okhttp3.internal.platform.Platform log
정보: Accept: text/plain, application/json, application/*+json, */*
6월 20, 2019 8:14:50 오전 okhttp3.internal.platform.Platform log
정보: --> END GET
6월 20, 2019 8:14:51 오전 okhttp3.internal.platform.Platform log
정보: <-- 200  http://요청주소 (61ms)
6월 20, 2019 8:14:51 오전 okhttp3.internal.platform.Platform log
정보: Server: nginx/1.12.0
6월 20, 2019 8:14:51 오전 okhttp3.internal.platform.Platform log
정보: Date: Wed, 19 Jun 2019 23:14:51 GMT
6월 20, 2019 8:14:51 오전 okhttp3.internal.platform.Platform log
정보: Content-Type: application/json;charset=UTF-8
6월 20, 2019 8:14:51 오전 okhttp3.internal.platform.Platform log
정보: Transfer-Encoding: chunked
6월 20, 2019 8:14:51 오전 okhttp3.internal.platform.Platform log
정보: Connection: keep-alive
6월 20, 2019 8:14:51 오전 okhttp3.internal.platform.Platform log
정보: X-Content-Type-Options: nosniff
6월 20, 2019 8:14:51 오전 okhttp3.internal.platform.Platform log
정보: X-XSS-Protection: 1; mode=block
6월 20, 2019 8:14:51 오전 okhttp3.internal.platform.Platform log
정보: Cache-Control: no-cache, no-store, max-age=0, must-revalidate
6월 20, 2019 8:14:51 오전 okhttp3.internal.platform.Platform log
정보: Pragma: no-cache
6월 20, 2019 8:14:51 오전 okhttp3.internal.platform.Platform log
정보: Expires: 0
6월 20, 2019 8:14:51 오전 okhttp3.internal.platform.Platform log
정보: X-Frame-Options: SAMEORIGIN
6월 20, 2019 8:14:51 오전 okhttp3.internal.platform.Platform log
정보: vary: accept-encoding
6월 20, 2019 8:14:51 오전 okhttp3.internal.platform.Platform log
정보: Set-Cookie: vrid=rBRdbF0Kweu6DCxNAwMgAg==; path=/
6월 20, 2019 8:14:51 오전 okhttp3.internal.platform.Platform log
정보: 
6월 20, 2019 8:14:51 오전 okhttp3.internal.platform.Platform log
정보: 응답결과
6월 20, 2019 8:14:51 오전 okhttp3.internal.platform.Platform log
정보: <-- END HTTP (2309-byte body)

로그가 사용하는 logger의 포맷을 따르지 않기 때문에 이 부분을 맞추기 위해 따로 interceptor를 구현하는게 좋을 것 같다.

netty의 경우는 확인하지 않았다.