RequestBody의 내용을 로그로 남기고 싶다.

다음은 최초에 제가 가졌던 니즈입니다.

1. POST 방식으로 호출되는 http request의 payload를 로그로 남기고 싶다.
2. controller 내부에서 한땀 한땀 로그로 남기는 방법 말고 다른 방법으로 남겨보고 싶다.

스프링 프레임워크 위에서 비즈니스 로직을 구현하고 있지만, 스프링 기반의 프로젝트의 구조에 관심을 이제서야 조금씩 가지다 보니 새롭고 좋네요. 한번도 완독해본적 없는 토비의 스프링이나 스프링 인 액션을 찬찬히 다시 한번 봐야겠습니다. 올해는 꼭 성공하면 좋겠네요.

일단 서비스가 돌아가고 있는 프로젝트의 소스 코드를 쭉 훑어보았습니다. 우선 기존에 쌓이고 있는 로그를 읽어가며 역으로 소스코드를 따라 들어가보았습니다. config 관련된 클래스들을 별도의 패키지에서 관리하고 있는데요. WebMvcConfigurationSupport 클래스를 상속받은 ServletApplicationContextConfig 가 있고, HandlerInterceptorAdapter 를 상속하여 구현한 인터셉터들이 있네요. 구현된 인터셉터들은 ServletAppliationContextConfig 내에서 등록하여 사용하고 있었습니다. 인터셉터의 내부에서 HttpRequest의 내용을 간략하게 남기고 있는 것을 보아하니, 별도의 인터셉터 클래스를 만들어 주어 request의 body를 찍어주게 하면 될 것 같은 느낌을 받았습니다.

스트림을 읽어들인 다음 문자열로 변환 시킨 후 로그로 남기도록 구현하였습니다. HandlerInterceptorAdapter 를 상속하여 만든 ApiLoggingInterceptor 클래스의 afterCompletion() 메소드에 이쁘게 로그를 찍어주도록 만들었습니다. 기쁜 마음으로 톰캣 인스턴스를 띄우고, http request를 하나 날려보았습니다. 찍히길 기대했던 로그는 안찍히고 다른 로그가 올라오네요. 별거 아니라고 생각하며 기쁜 마음으로 서버 로그가 찍히길 기다렸는데, 이미 스트림이 닫혀있다는 예외 메시지만 출력되었습니다. 다음과 같이요.

ERROR 2017-01-18 10:16:59 [http-bio-8080-exec-8] servlet.HandlerExecutionChain.triggerAfterCompletion:173 - HandlerInterceptor.afterCompletion threw exception java.io.IOException: Stream closed

atferComplete에 넣어서 그런가 싶어 로그 출력을 담당하고 있는 메소드의 위치를 살포시 옮겨봅니다. preHandle() 로 옮겨보았습니다. 음… 역시 안되네요. 이전에 보았던 메시지와 비슷한 듯, 비슷하지 않은 듯, 비슷한 에러 로그를 만났습니다.

org.springframework.http.converter.HttpMessageNotReadableException: Could not read JSON: Stream closed; nested exception is java.io.IOException: Stream closed

이전과 차이가 있다면 http request message의 body는 제가 원하는대로 잘 남았습니다. 추측해보건데 아마도 controller에서 사용중 인 @RequestBody 어노테이션도 비슷한 방식으로 http request의 내용을 읽어들이는 것 같습니다. 추측일 뿐 Spring MVC가 @RequestBody 어노테이션을 어떻게 처리하는지에 대한 상세한 내용은 나중에 알아보겠습니다. 아무튼 preHandle() 에서 이미 스트림을 다 읽어버린 것 같네요. @RequestBody 의 구현은 차차 알아보도록 하고, 원래 목표에 집중하겠습니다.

HandlerInterceptionAdapter 를 상속한 ApiLoggingInterceptor 에서 http request의 body를 읽어들이는 방법은 쉽게 되지 않을 것 같아 조금 더 찾아 보았습니다. 물론 방법이 있긴 하겠지만, 일단 지금은 잘 모르겠습니다. 동일 레벨에서 처리하기 보다는 한단계 더 위로 올라가서 전처리하면 되지 않을 까 싶어 프로젝트의 소스코드를 다시 찾아 보았습니다. 우선 ServletApplicationContextConfig 가 어디에서 선언되는지 찾아 보았습니다. WebApplicationInitializer 인터페이스의 구현체에 오버라이딩된 onStart() 메소드에서 등록되었습니다. onStartup() 메소드를 보니 이미 누군가 filter 라는 걸 추가해서 사용하고 있네요. sercurity, xss 처리를 위한 처리를 담당하고 있는 것 같습니다.각 필터들을 보니 오버라이드된 doFilter() 메소드에서 HttpRequestWrapper를 상속한 클래스의 인스턴스를 생성하고 이를 filterChain에 등록시키는 것을 확인할 수 있었습니다. 그래서 혹시나 싶어 저도 따라해 보았습니다. 우선 HttpServletRequestWrapper를 상속받아 ReadableRequestBodyWrapper 클래스를 만들어보았습니다.

// ReadableRequestBodyWrapper.java
public class ReadableRequestBodyWrapper extends HttpServletRequestWrapper {
	private byte[] bytes;
	private String requestBody;

	public ReadableRequestBodyWrapper(HttpServletRequest request) throws IOException{
		super(request);

		InputStream in = super.getInputStream();
		bytes = IOUtils.toByteArray(in);
		requestBody = new String(bytes);
	}

	@Override
	public ServletInputStream getInputStream() throws IOException {
		final ByteArrayInputStream bis = new ByteArrayInputStream(bytes);
		return  new ServletImpl(bis);
	}

	public String getRequestBody() {
		return this.requestBody;
	}

	class ServletImpl extends ServletInputStream{
		private InputStream is;
		public ServletImpl(InputStream bis){
			is = bis;
		}

		@Override
		public int read() throws IOException {
			return is.read();
		}

		@Override
		public int read(byte[] b) throws IOException {
			return is.read(b);
		}
	}
}

그리고 Filter 인터페이스의 구현체인 RequestBodyLoggingFilter 클래스를 다음과 같이 정의 했습니다. 래퍼 클래스에서 읽어들인 내용을 servletReqeust의 attribute로 선언해주었습니다. 그리고 래퍼클래스를 필터 체인에 추가합니다. 예외가 발생하면 최초에 전달받은 request를 넘겨주도록 했습니다. 현재 서비스 중인 소스 코드여서 그런지 필터 처리하는 과정에서 이슈가 발생할까 두려운 마음에 조심스레 다루어봅니다.

// RequestBodyLoggingFilter.java
public class RequestBodyLoggingFilter implements Filter {
	@Override
	public void destroy() {

	}

	@Override
	public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
		try {
			ReadableRequestBodyWrapper wrapper = new ReadableRequestBodyWrapper((HttpServletRequest)request);
			wrapper.setAttribute("requestBody", wrapper.getRequestBody());
			chain.doFilter(wrapper, response);
		} catch (Exception e) {
			chain.doFilter(request, response);
		}
	}

	@Override
	public void init(FilterConfig filterConfig) throws ServletException {

	}
}

앞서 구현한 RequestBodyLoggingFilter 를 WebApplicationInitializer 의 onStartup() 메소드에서 필터로 등록을 해주었습니다.

// WebApplicationInitializer.class
public class WebApplicationInitializer extends WebApplicationInitializer {

	@Override
	public void onStartup(ServletContext servletContext) throws ServletException {
		addRequestBodyFilter(servletContext);
	}

	private void addRequestBodyFilter(ServletContext servletContext) {
		FilterRegistration requestBodyFilter = servletContext.addFilter("requestBodyFilter", RequestBodyLoggingFilter.class);
	}

}

마지막으로 request의 attribute로 설정한 requestBody를 interceptor에서 꺼내어 출력해보았습니다.

// ApiLoggingInterceptor.class
public class ApiLoggingInterceptor extends HandlerInterceptorAdapter {
    private final static String REQUEST_POST = "POST";

    @Override
    public boolean preHandle(HttpServletRequest request,
                             HttpServletResponse response, Object handler) throws Exception {

        if (REQUEST_POST.equals(request.getMethod())) {
            log.info("[+] PATH : {}, PARAMS {}\n{}", request.getPathInfo(), request.getAttribute("requestBody"), printExecTime(request));
        }

        return true;
    }

}

음, 아주 좋아요. 제가 처음에 하고 싶었던 것이 완성이 되었습니다. 다시 간단하게 과정을 정리하자면

1. ServletRequest를 Wrapper로 한번 감싸면서 request의 content를 읽어들여 request의 attribute로 선언한다.
2. 1번에서 구현한 Wrapper를 필터에 등록하여 모든 request에 대해서 작동하도록 한다.
3. Interceptor 에서 request의 attribute를 꺼내어 읽어줍니다.

구현하고 곰곰히 생각해보니 AOP를 이용해서 구현해도 괜찮았을 것 같네요. Controller에 구현되어 있는 메소드들이 호출되는 시점에 파라미터들을 출현하게 해주는 것도 좋은 방법이 될 것 같은 생각이 듭니다. 어째됐든 결과적으로는 처음 원했던 기능은 정상적으로 동작함을 확인했습니다. 다만, 이 구현이 제대로된 구현인지 잘 모르겠습니다. 서블릿과 스프링 사이를 오가는 구조 내에서 어떤 권장 패턴인지를 모르겠네요. 이 부분은 추후에 다시 깊게 파봐야 할 것 같네요. 로그 출력하는 것에만 집중하느라 중간 중간 만났던 서블릿과 스프링의 일부 개졈들을 수박 겉핥기 식으로 확인한 것들에 대해서도 다시 한번 찾아 리서치를 해볼까 합니다.

• filter와 interceptor는 무엇이고 어떤 차이가 있는지
• Dispatcher Servlet은 무엇인지
• Spring MVC에서 @RequestBody는 어떤 식으로 HttpRequest의 내용을 읽어 들이는지

추가적으로 좀 더 정확하게 구조를 파악하기 위해서 필터와 인터셉터 설정을 처음부터 해보는 것도 나쁘지 않을 것 같네요.

• 아무런 설정도 되어 있지 않은 Spring 초기 상태에서 직접 위의 과정들을 수행
• AOP를 통해서 controller 클래스의 메소드가 실행될때 파라미터를 출력