Spring boot HTTP Request/Response Log 남기기

티스토리 뷰

Spring Framework

Spring boot HTTP Request/Response Log 남기기

터프남 2022. 8. 19. 18:20

728x90

환경

spring boot 2.6.10

gradle dependency

dependencies {
    implementation 'org.springframework.boot:spring-boot-starter-web'
    compileOnly 'org.projectlombok:lombok'
    annotationProcessor 'org.projectlombok:lombok'
    testImplementation 'org.springframework.boot:spring-boot-starter-test'
    testCompileOnly 'org.projectlombok:lombok'
    testAnnotationProcessor 'org.projectlombok:lombok'

}

내 서버의 Request와 Response에 대한 로그를 찍고 싶었다. RequestURI, Content-type, Encoding , ReqeustParameter와 RequestBody 필요하다면 클라이언트에게 내려줄 ResponseBody까지 로그로 남기고 싶었다.

열심히 구글링을 하면서 알게 된 건

HttpServletRequest의 getReader() 메서드나 getInputStream()을 통해서 body의 값은 한 번만 읽을 수 있다.

실제 HttpServletRequest를 구현한 org.apache.catalina.connector.Request의 파일 내용중 getInputStream과 getReader의 내용을 보면 Exception을 발생시키는 것을 확인할 수 있다.

@Override
public ServletInputStream getInputStream() throws IOException {

    if (usingReader) {
        throw new IllegalStateException(sm.getString("coyoteRequest.getInputStream.ise"));
    }

    usingInputStream = true;
    if (inputStream == null) {
        inputStream = new CoyoteInputStream(inputBuffer);
    }
    return inputStream;

}

@Override
public BufferedReader getReader() throws IOException {

    if (usingInputStream) {
        throw new IllegalStateException(sm.getString("coyoteRequest.getReader.ise"));
    }

    // InputBuffer has no easily accessible reference chain to the Context
    // to check for a default request character encoding at the Context.
    // Therefore, if a Context default should be used, it is set explicitly
    // here. Need to do this before setting usingReader.
    if (coyoteRequest.getCharacterEncoding() == null) {
        // Nothing currently set explicitly.
        // Check the content
        Context context = getContext();
        if (context != null) {
            String enc = context.getRequestCharacterEncoding();
            if (enc != null) {
                // Explicitly set the context default so it is visible to
                // InputBuffer when creating the Reader.
                setCharacterEncoding(enc);
            }
        }
    }

    usingReader = true;

    inputBuffer.checkConverter();
    if (reader == null) {
        reader = new CoyoteReader(inputBuffer);
    }
    return reader;
}

실제로 그런지 MockMvc를 통해 테스트 해보기로 했다.

(1) Logging을 할 Filter 클래스를 만들어서 Bean으로 만든다.

@Slf4j
@Component
public class LoggingFilter extends OncePerRequestFilter {

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {

        ServletInputStream inputStream = request.getInputStream();
        new BufferedReader(new InputStreamReader(inputStream))
        		.lines()
	                .forEach(log::info);
        filterChain.doFilter(request, response);
    }
}

일부러 Request 본문(body)을 소비하려고 getInputStream()을 읽어서 로그를 찍게 해 놨다.

(2) ServletConfig를 만들고 Spring boot에 내가 만든 LoggingFilter를 등록해주는 작업을 했다.

여러 다른 블로그를 보면 이렇게 하지 않고 Filter 구현 클래스에 (이 글 기준 LoggingFilter) @WebFilter 어노테이션과 @ServletComponentScan을 활용해서 해도 된다.. 주의점도 있는 것 같다. (https://taetaetae.github.io/2020/04/06/spring-boot-filter/)

@Configuration
public class ServletConfig {

    @Bean
    public FilterRegistrationBean<Filter> filterRegistrationBean() {
        FilterRegistrationBean<Filter> filter = new FilterRegistrationBean<>();
        filter.setFilter(new LoggingFilter()); //필터 등록
        filter.addUrlPatterns("/*");	// 모든요청에 filter 거쳐가게 설정
        return filter;
    }
}

(3) 요청 컨트롤러를 만들었다. 테스트 목적

PostMapping에 @RequestBody 어노테이션으로 본문에 Person형태의 json 데이터가 들어오면 Person 객체로 역직렬 화하는데 이건 실패할 것이다.

@Slf4j
@RestController
@SpringBootApplication
public class SpringHttpLoggingApplication {

    @GetMapping("/hello")
    public String hello() {
        return "world";
    }

    @PostMapping("/json")
    public ResponseEntity<Person> readServletStream(@RequestBody Person person) {
        log.info("person = {}", person);
        return ResponseEntity.ok(person);
    }

    public static void main(String[] args) {
        SpringApplication.run(SpringHttpLoggingApplication.class, args);
    }

}

(4) MockMvc 테스트를 해본다. POST 요청으로 요청 본문(body)에 값을 넣어서 보내본다.

@Test
@DisplayName("POST 요청 RequestWrapper없이")
void POST_WITHOUT_REQUEST_WRAPPER() throws Exception {

    String valueAsString = objectMapper.writeValueAsString(new Person("1", "test"));

    log.info("valueAsString = {}", valueAsString);
    mockMvc.perform(post("/json")
                    .content(valueAsString)
                    .contentType(MediaType.APPLICATION_JSON))
            .andExpect(status().isBadRequest())
            .andDo(print());
}

기대하는 값을 isBadRequest() == 400 이므로 테스트는 통과한다. 그럼 무슨 Exception이 발생했을까?

MockHttpServletRequest:
      HTTP Method = POST
      Request URI = /json
       Parameters = {}
          Headers = [Content-Type:"application/json;charset=UTF-8", Content-Length:"24"]
             Body = {"id":"1","name":"test"}
    Session Attrs = {}

Handler:
             Type = com.example.logging.SpringHttpLoggingApplication
           Method = com.example.logging.SpringHttpLoggingApplication#readServletStream(Person)

Async:
    Async started = false
     Async result = null

Resolved Exception:
             Type = org.springframework.http.converter.HttpMessageNotReadableException

ModelAndView:
        View name = null
             View = null
            Model = null

FlashMap:
       Attributes = null

MockHttpServletResponse:
           Status = 400
    Error message = null
          Headers = []
     Content type = null
             Body = 
    Forwarded URL = null
   Redirected URL = null
          Cookies = []

org.springframework.http.converter.HttpMessageNotReadableException 예외가 발생했다.

HttpMessageNotReadableException 즉 HttpMessage를 읽을 수 없어서 나는 예외이다. Filter에서 한번 본문을 소비했기 때문에 읽을 수 없다.

그렇다면 어떻게 해야 할까? 스프링은 이럴 때를 대비해서 HttpRequestServletWrapper라는 클래스를 만들어 놨다.

HttpRequestServletWrapper를 직접 확장한 클래스를 만들어서 구현해도 되지만 이미 스프링이 HttpRequestServletWrapper를 확장한 ContentCachingRequestWrapper를 만들어놨다. HttpServletRequest와 HttpServletResponse를 ContentCachingRequestWrapper로 감싸서 chain 시켜주면 본문을 다시 읽을 수 있다. 그런데 여기서 다시 읽는다는 것은 두 번 읽을 수 있다는 것이 아니라 최초 요청 시 본문을 캐시 해둔 상태인데 그 값을 사용한다는 이야기다.

@Slf4j
@Component
public class LoggingFilter extends OncePerRequestFilter {

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
        
        ContentCachingRequestWrapper requestWrapper = new ContentCachingRequestWrapper(request);
        ContentCachingResponseWrapper responseWrapper = new ContentCachingResponseWrapper(response);
        filterChain.doFilter(requestWrapper, responseWrapper);
        
        //필수! 
        responseWrapper.copyBodyToResponse();
    }
    
    //필터 로깅 작업...
    //.....
}

이전과는 달라진 점이 ContentCachingRequestWrapper를 생성할 때 HttpServletRequest와 HttpServletResponse를 래핑 해서 넘겨주는 것이다. 중요한 점은 마지막 줄에 copyBodyToResponse() 메서드를 실행해줘야지 클라이언트에서 응답을 받을 수 있다.

c.example.logging.filter.LoggingFilter   : [REQUEST] POST - /json 200
c.example.logging.filter.LoggingFilter   : Headers : {content-length=36, host=localhost:8080, content-type=application/json, connection=Keep-Alive, accept-encoding=gzip,deflate, user-agent=Apache-HttpClient/4.5.13 (Java/17.0.3)}
c.example.logging.filter.LoggingFilter   : Request : {
  "id": 999,
  "name": "content"
}
c.example.logging.filter.LoggingFilter   : Response : {"id":"999","name":"content"}

그래서 이걸 언제 쓸까?

Filter와 AOP 또는 Interceptor를 검색했을 때 블로그에 가장 많이 나오는 이미지이다. Filter는 사용자와 DispatcherServlet 사이에 위치해 있으며 사용자의 처음 요청과 끝에 응답하는 역할을 한다. 그렇기 때문에 Filter는 보안과 인가 관련 그리고 암호화 복호화 또는 인코딩 디코딩에 많이 쓰인다. 나처럼 Request나 Response를 로깅하는데도 쓸 수 있다.