Spring RestTemplate 사용 시 HTTP request, response 로그 남기기

spring의 RestTemplate을 이용하면 대게 다음의 exchange 메소드를 이용하여 외부 API와 연동을 하게 된다.

ResponseEntity<P> response = restTemplate.exchange(requestUrl, httpMethod, requestEntity, p);

위의 exchange 메소드를 이용하여 연동을 할 때 HTTP request, response 전문을 로그로 남기고 싶을 때가 있어서 그 방법을 찾아보게 되었다.

첫 번째 방법은 log4j를 이용하여 로그를 남기는 방법인데 이 방법은 한 줄 로그로 남길 수 없다는 단점이 있어 포기했다. 무슨 말이냐하면 아래와 같이 여러 줄로 로그가 기록된다는 것이다. 여러 줄로 출력되는 로그는 멀티 쓰레드 환경에서는 오류에 대한 원인을 찾기가 힘들다.

[2015-10-14 16:49:49 DEBUG o.a.h.headers][273] - >> GET /test/check.json HTTP/1.1

[2015-10-14 16:49:49 DEBUG o.a.h.headers][276] - >> Accept: application/json, application/*+json

[2015-10-14 16:49:49 DEBUG o.a.h.headers][276] - >> Content-Type: application/json

[2015-10-14 16:49:49 DEBUG o.a.h.headers][276] - >> Host: test.com:8080

[2015-10-14 16:49:49 DEBUG o.a.h.headers][276] - >> Connection: Keep-Alive

[2015-10-14 16:49:49 DEBUG o.a.h.headers][276] - >> User-Agent: Apache-HttpClient/4.2.6 (java 1.5)

[2015-10-14 16:49:49 DEBUG o.a.h.wire][63] - << "HTTP/1.1 200 OK[\r][\n]"

[2015-10-14 16:49:49 DEBUG o.a.h.wire][63] - << "Content-Type: application/json[\r][\n]"

[2015-10-14 16:49:49 DEBUG o.a.h.wire][63] - << "Content-Length: 173[\r][\n]"

[2015-10-14 16:49:49 DEBUG o.a.h.wire][63] - << "Server: WebServer/9239402.2329 Instance/2.464680819[\r][\n]"

[2015-10-14 16:49:49 DEBUG o.a.h.wire][63] - << "[\r][\n]"

두 번재 방법은 RestTemplate에 interceptors 를 추가하는 것이다.

<bean id="restTemplate" class="org.springframework.web.client.RestTemplate">

<property name="interceptors">

<list>

<bean class="com.test.RestTemplateLoggingRequestInterceptor" />

</list>

</property>

</bean>

RestTemplate이 상속하고 있는 InterceptingHttpAccessor 클래스를 확인해 보면 interceptors를 주입받을 수 있게 되어 있다. 다음과 같이 로그 기록용 interceptor 클래스를 생성한 후 등록해 주면 HTTP request, response 로그를 남길 수 있다.

	@Slf4j
	public class RestTemplateLoggingRequestInterceptor implements ClientHttpRequestInterceptor {
	/**
	* <pre>
	* intercept
	*
	* <pre>
	*
	* @param request
	* @param body
	* @param execution
	* @return
	* @throws IOException
	*/
	@Override
	public ClientHttpResponse intercept(HttpRequest request, byte[] body, ClientHttpRequestExecution execution) throws IOException {
	// 사용자 정보 추출
	String userId = "aaaa";
	// request log
	URI uri = request.getURI();
	traceRequest(request, body, userId);
	// execute
	ClientHttpResponse response = execution.execute(request, body);
	// response log
	traceResponse(response, userId, uri);
	return response;
	}
	/**
	* <pre>
	* traceRequest
	*
	* <pre>
	* @param request
	* @param body
	* @param userId
	* @throws IOException
	*/
	private void traceRequest(HttpRequest request, byte[] body, String userId) throws IOException {
	StringBuilder reqLog = new StringBuilder();
	reqLog.append("[REQUEST] ");
	reqLog.append("Uri : " + request.getURI());
	reqLog.append(", Method : " + request.getMethod());
	reqLog.append(", Request Body : " + new String(body, StandardCharsets.UTF_8));
	reqLog.append(", UserId : " + userId);
	log.info(reqLog.toString());
	}
	/**
	* <pre>
	* traceResponse
	*
	* <pre>
	* @param response
	* @param userId
	* @throws IOException
	*/
	private void traceResponse(ClientHttpResponse response, String userId, URI uri) throws IOException {
	InputStream is = response.getBody();
	byte[] bodyData = IOUtils.toByteArray(is);
	StringBuilder resLog = new StringBuilder();
	resLog.append("[RESPONSE] ");
	resLog.append("Uri : " + uri);
	resLog.append(", Status code : " + response.getStatusCode());
	resLog.append(", Response Body : " + new String(bodyData, StandardCharsets.UTF_8));
	resLog.append(", UserId : " + userId);
	log.info(resLog.toString());
	}
	}

view raw RestTemplateLoggingRequestInterceptor.java hosted with ❤ by GitHub

허나 여기서 끝이 아니다.

RestTemplateLoggingRequestInterceptor 클래스에서 response로그를 찍을 때 byte[] bodyData = IOUtils.toByteArray(is); 코드를 이용하여 response body의 데이터를 stream을 통해 읽어온 후 해당 stream을 close해 버린다. 그렇기 때문에 다른 코드상에서 response의 body를 읽게 되면 아래와 같은 오류 메세지를 만날 수 있게 된다.

Attempted read from closed stream

이 문제를 해결해 줄 수 있는 클래스가 BufferingClientHttpRequestFactory 이다.

BufferingClientHttpRequestFactory 코드 내에는 response의 body를 copy하는 로직이 있기 때문에 Attempted read from closed stream 오류를 회피할 수 있다.

최종적인 설정은 다음과 같다.

<bean id="connectionManager" class="org.apache.http.impl.conn.PoolingClientConnectionManager">

<property name="maxTotal" value="200" />

<property name="defaultMaxPerRoute" value="100" />

</bean>

<bean id="httpClient" class="org.apache.http.impl.client.DefaultHttpClient">

<constructor-arg ref="connectionManager"/>

</bean>

<bean id="httpClientFactory" class="org.springframework.http.client.HttpComponentsClientHttpRequestFactory">

<constructor-arg ref="httpClient" />

<property name="connectTimeout" value="10" />

<property name="readTimeout" value="10" />

</bean>

<bean id="bufferingClientHttpRequestFactory" class="org.springframework.http.client.BufferingClientHttpRequestFactory">

<constructor-arg ref="httpClientFactory" />

</bean>

<bean id="restTemplate" class="org.springframework.web.client.RestTemplate">

<constructor-arg ref="bufferingClientHttpRequestFactory" />

<property name="messageConverters">

<list>

<bean class="org.springframework.http.converter.StringHttpMessageConverter">

<constructor-arg value="UTF-8" />

</bean>

<bean class="org.springframework.http.converter.json.MappingJacksonHttpMessageConverter">

<property name="objectMapper">

<bean class="com.test.CustomObjectMapper" />

</property>

</bean>

<bean class="org.springframework.http.converter.xml.Jaxb2RootElementHttpMessageConverter" />

</list>

</property>

<property name="interceptors">

<list>

<bean class="com.test.interceptor.RestTemplateLoggingRequestInterceptor" />

</list>

</property>

</bean>