Filter로 사용자의 요청과 응답을 로그로 남겨보며 만난 다양한 경험에 대한 기록이다.
요청과 응답을 로깅해보자
스프링 MVC를 사용하며 사용자의 요청과, 응답을 로그로 남기고 싶었다.
로그를 남기는 방법에는 크게 3가지 방법이 있었다.
- AoP
- Interceptor
- Filter
결론적으로는 Filter를 사용해 로그를 남기기로 결정했다. 나는 왜 이런 결정을 내리게 되었을까?
일단 세가지 방법이 동작하는 시점에 대해 알아볼 필요가 있다.
동작 시점
세가지 방법은 각기 다른 시점에서 동작한다.
스프링 MVC와 스프링 시큐리티를 사용하는 상황에서 요청은 그림과 같은 흐름으로 전달된다.
- 모든 요청은 서블릿 필터들을 통과한다.
- 서블릿 필터중 하나인
DelegatingFilterProxy가 요청을 시큐리티 필터 체인으로 위임한다. - 시큐리티 필터 체인을 통과한 요청은 남은 서블릿 필터를 통과한다.
- 모든 서블릿 필터를 통과한 요청은 프런트 컨트롤러 역할을 수행하는 디스패쳐 서블릿으로 들어온다.
- 디스패처 서블릿에서 각 컨트롤러로 요청을 보내주게 된다.
AoP
스프링 AoP는 빈의 비즈니스 로직의 횡단 관심사를 정의하는데 사용한다.
그림에서 3의 위치에 해당한다.
AoP는 비즈니스 로직이 있는 Service나 Controller 레이어에서 사용되며 포인트컷을 정의해 공통로직을 수행하는데 사용한다.
Interceptor
Interceptor 는 Dispatcher Servlet 을 지난 요청이 핸들러를 찾아가기전에 동작한다.
그림에서 2에 해당한다.
Filter
Filter 는 설정에 따라 다르지만 요청이 컨트롤러로 들어가기전 모든 시점에서 동작할 수 있다.
그림에서 빨간색 박스에 해당한다.
로그의 목적
나는 모든 요청에 대한 로그를 남기고 싶었다. 성공한 요청뿐만 아니라, 실패한 요청까지 남기고 싶었다.
하지만 Interceptor 는 디스패처 서블릿 이후에 실행된다.
하지만 요청이 필터에서 거절된다면 인터셉터까지 닿을 수 없기 때문에 인터셉터는 후보군에서 제외했다.
즉 AoP, Filter두가지 방법중 고민해봤다.
AoP 로깅
처음에는 모든 메서드에서 동작할 수 있는 AoP를 사용해 로그를 남기기로 결정했다.
모든 Controller 의 메서드에 대해 RequestContextHolder 로부터 요청, 응답 컨텍스트를 얻어내 로깅을 할 수 있었다.
@Before("controllerMethods()")
public void logRequest(JoinPoint joinPoint) {
requestTime = System.currentTimeMillis();
Map<String, Object> requestLog = new HashMap<>();
id = UUID.randomUUID().toString();
HttpServletRequest httpRequest = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getRequest();
...
}하지만, 로그인에 실패하거나 토큰에 오류가 있는 경우는 필터단에서 요청이 거절되기 때문에 컨트롤러까지 들어올 수 없었다.
필터에 AoP를 적용하려 시도해봤지만, 빈을 프록시로 등록하는 AoP 동작 특성상 빈이 아닌 타겟에는 적용할 수 없었다.
이로인해 스프링 시큐리티 필터에서 거절되는 요청은 AoP로 로그를 남길 수 없다는 문제가 생겼다.
이러한 이유로 AoP 대신 Filter로 로깅하는 방법을 선택하게 되었다.
Filter 로깅
우선 스프링 시큐리티를 사용하는 상황에서 필터에는 어떤종류가 있는지 알아야 한다.
- 서블릿 필터
- 시큐리티 필터
서블릿 필터는 스프링 컨텍스트 외부인 서블릿 컨테이너에 위치해있다.
하지만 스프링 시큐리티에서 사용하는 시큐리티 필터는 스프링 컨테이너에 위치해 있다.
그래서 서블릿 필터중 하나인DelegatingFilterProxy 는 서블릿 필터에서 스프링 컨테이너로 요청을 위임해 스프링 컨텍스트에서 요청을 처리할 수 있도록 해주는것이다.
둘중 어느 필터에 로그필터를 추가할지 고민하다가, 서블릿 필터로 추가하기로 했다.
이유는 시큐리티 필터는 보안과 관련된 필터만 존재하는것이 맞는것 같고, 그 외 로직은 서블릿 필터에 추가하는것이 맞을것 같아서다.
필터 등록
간단한 필터를 만들고 등록을 해보려 했다.
public class LoggingFilter implements Filter {
@Override
public void init(FilterConfig filterConfig) throws ServletException {
Filter.super.init(filterConfig);
}
@Override
public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)
throws IOException, ServletException {
System.out.println("log!");
chain.doFilter(request, response);
}
@Override
public void destroy() {
}
}서블릿 필터를 등록할 수 있는 다양한 방법들이 있었고 나는 FilterRegistrationBean 를 사용해 등록을 했다.
DelegatingFilterProxy 와 유사하지만 이는 필터 자체이고 요청을 스프링 컨텍스트로 위임하는 역할을 하지만, FilterRegistrationBean 은 필터를 빈으로 감싸 등록시켜 준다.
필터 자체가 빈으로 등록되는것이 아니다
순서 설정
Filter를 등록할때 순서를 설정해줘야 한다.
filterRegistrationBean.setOrder(N);나의 경우 시큐리티 필터 체인보다 먼저 실행되어야 하기 때문에 이보다 앞선 순서가 필요했다.
필터 체인보다 앞선 순서에 배치하기 위해선 DelegatingFilterProxy 의 순서를 알아야 했지만 인터넷을 아무리 찾아봐도 찾을 수 없었다.
결국 디버깅으로 필터 순서를 알아보기로 했다.
디버깅으로 DelegatingFilterProxy 의 순서 찾아보기
일단 필터를 등록하고, 내 필터에 디버거를 걸어 Filter Chain을 뒤져보기로 했다.
chain.doFilter() 를 타고 내려가니, 필터 체인을 만날 수 있었다.
LogginFilter.doFilter() -> ApplicationFilterChain.doFilter() -> ApplicationFilterChain.internalDoFilter()
서블릿 필터 체인을 보니 DelegatingFilterProxy 도 보이고 내가 추가한 LoggingFilter 도 확인할 수 있었다.
그리고 다행히도 DelegatingFilterProxy 의 order 도 알 수 있었다.
order가 -100 으로 설정되어 있었다...
그래서 내가 아무리 order를 0, -1 로 설정해봐도 시큐리티뒤에 수행된거였구나 싶었다.
아무튼 DelegatingFilterProxy의 순서를 알았으니 이보다 낮은 숫자로 설정해 미리 수행되도록 설정했다.
filterRegistrationBean.setOrder(-101);이렇게 설정하니, 시큐리티 필터 체인보다 먼저 동작하는것을 확인할 수 있었다.
로그출력
이제 필터에서 로그를 잡아 출력하는 일만 남았다.
헤더, url, parameter 등의 정보를 얻는데는 큰 무리가 없었지만, Body를 얻는데 큰 문제가 있었다.
Body는 Stream으로 전달된다
제목 그대로 Body는 stream 으로 전달되었다.
Request, Response 모두 InputStream, OutputStream 으로만 Body가 전달되어서, 만약 로깅필터에서 이 스트림을 소모해 버린다면 실제 비즈니스 로직에서는 소비할 스트림이 없어지는 문제였다.
실제로 로그 필터에서
Request의InputStream을소모한다면Controller에서 바디를 받을 수 없었고, 다른 시큐리티 필터에서Response의OutputStream을 소모한다면 로그 필터에서 바디를 받을 수 없었다.
만약 요청이 로그 필터에 도착했을때 Request나, Response에 저장된 스트림을 변경할 수 있다면 쉬웠을텐데 그런 방법도 없었다.
이 문제를 해결하기 위해 구글링을 하다 스트림을 래핑하는 방법에 대해 알게되었다.
https://howtodoinjava.com/java/servlets/httpservletrequestwrapper-example-read-request-body/
기존 스트림을 래핑해 read() , write() 메서드가 호출되면 내부 ByteArrayOutputStream 에 동일한 값을 저장하고, 나중에 이 값을 사용하는 방식이다.
이를 위해서 InputStream래퍼, Request래퍼, OutputStream래퍼, Response래퍼를 만들어 사용했다.
LoggingServletInputStream
이 스트림 래퍼는 RequestBody의 InputStream을 래핑해 다른곳에서 스트림을 읽을때 (ex @RequestBody) 오버라이딩된 이 래퍼의 read() 가 동작함으로써, 같은 값을 내부의 ByteArrayOutputStream 에 저장한다.
public class LoggingServletInputStream extends ServletInputStream {
private ByteArrayOutputStream byteArrayOutputStream;
private ServletInputStream original;
public LoggingServletInputStream(ServletInputStream original) {
this.original = original;
this.byteArrayOutputStream = new ByteArrayOutputStream();
}
@Override
public boolean isFinished() {
return original.isFinished();
}
@Override
public boolean isReady() {
return original.isReady();
}
@Override
public void setReadListener(ReadListener listener) {
original.setReadListener(listener);
}
@Override
public int read() throws IOException {
int data = original.read();
if (data != -1) {
byteArrayOutputStream.write(data);
}
return data;
}
@Override
public int read(byte[] b, int off, int len) throws IOException {
int bytesRead = original.read(b, off, len);
if (bytesRead > 0) {
byteArrayOutputStream.write(b, off, bytesRead);
}
return bytesRead;
}
public byte[] getBytes() {
return byteArrayOutputStream.toByteArray();
}
}LoggingHttpServletRequestWrapper
이 Request 래퍼는 위에서 설명한 InputStreamWrapper를 사용하기 위한 래퍼 클래스다. 기존 Request 객체에 InputStream을 변경할 수 없으므로, 이런 방법을 사용한다.
public class LoggingHttpServletRequestWrapper extends HttpServletRequestWrapper {
private LoggingServletInputStream loggingServletInputStream;
private ServletInputStream original;
public LoggingHttpServletRequestWrapper(HttpServletRequest request) throws IOException {
super(request);
this.original = request.getInputStream();
this.loggingServletInputStream = new LoggingServletInputStream(original);
}
@Override
public ServletInputStream getInputStream() throws IOException {
return loggingServletInputStream;
}
public byte[] getRequestData() {
return loggingServletInputStream.getBytes();
}
}LoggingFilter
로깅 필터에서 이 래퍼클래스들을 사용해 요청을 다음 필터로 넘겼다.
HttpServletRequest httpRequest = (HttpServletRequest) request;
HttpServletResponse httpResponse = (HttpServletResponse) response;
LoggingHttpServletRequestWrapper requestWrapper = new LoggingHttpServletRequestWrapper(httpRequest);
LoggingHttpServletResponseWrapper responseWrapper = new LoggingHttpServletResponseWrapper(httpResponse);
chain.doFilter(requestWrapper, responseWrapper);
String requestData = new String(requestWrapper.getRequestData(), Charset.defaultCharset());
String responseData = new String(responseWrapper.getResponseData(), Charset.defaultCharset());
Request의 경우 doFilter 전에 스트림을 읽어버리면 안된다. 그렇게 된다면 위에서 설명했듯 실제 컨트롤러에서 @RequestBody 로 InputStream 을 읽을 수 없어지고, 지금까지한 작업의 의미가 사라진다.
즉 @RequestBody 에서 InputStream 을 읽은뒤 스트림으로부터 복사한 ByteArrayOutputStream 를 가져와 사용해야한다.
이제 모든 데이터들을 이쁘게 출력하기만 하면 된다.
정리
스프링 MVC, 시큐리티 환경 에서 요청, 응답을 로깅하는 방법에 대해 찾아보고 직접 구현해봤다.
AoP, Filter를 사용해서 직접 구현해보고 구현해보진 않았지만 Interceptor를 포함해 각 방법의 장단점, 특징에 대해 알게되었다.
특히 AoP를 사용할때는 이미 객체로 만들어진 RequestBody, ResponseBody 를 사용해서 큰 어려움이 없었는데 Filter를 사용할때는 Request 객체, Response 객체를 얻는것은 쉬웠으나, 스트림으로 전달된 body 데이터를 받아내는과정이 어려웠다.
공부를 하며 필터에대해 자세히 알게되었고, 특히 I/O Stream 에 지식도 많이 얻을 수 있었다.
