요청 로그에 Body가 안나오는 문제 해결 (커스텀 Wrapper 도입)

배경

요청 로그를 살펴보는데 Body가 항상 비어있는 것을 확인하게 되었습니다.

실제로는 POST 요청으로 Body에 데이터를 담아서 요청을 보내고 있었습니다. 서버에서도 Body에서 데이터를 꺼내서 비즈니스 로직을 성공적으로 수행하고 있었습니다. 그러나 로그에서는 Body에 담긴 데이터를 보여주지 못하고 있었습니다.

InputStream 문제??

HttpServletRequest의 요청 바디는 InputStream으로 되어 있기에, 한 번 소비되면 값이 비어집니다.

 

@PostMapping("/test")
fun test(@RequestBody requestBody: TestRequest) {
			...
}

DispatcherServlet에서 @RequestBody 를 보고 요청 바디를 읽게 됩니다. 따라서 DispatcherServlet 읽기 전에 Body에 어떠한 처리를 해줘야 정상적으로 로깅을 할 수 있습니다.

Body를 캐싱하기 위한 ContentCacheRequestWapper

InputStream으로 읽어서 Body가 사라지기에 로깅되지 않는다는 것을 알았습니다. 그러면 캐싱하면 되지 되지 않을까요? 이를 위한 클래스를 스프링에서는 이미 제공하고 있습니다.

HttpServeltRequest를 ContentCachingRequestWapper로 감싸게 되면 InputStream을 읽을 때 캐싱을 하게 됩니다. 그리고 로그를 찍을 수 있게 되는 것이죠.

하지만 여전히 비어있는 Body

이를 위해 필더에서 HttpServeltRequest를 ContentCachingRequestWapper로 감싸주는 작업을 했습니다.

 

class LoggingWrappingFilter : Filter {
    override fun doFilter(
        request: ServletRequest,
        response: ServletResponse,
        chain: FilterChain,
    ) {
        val wrappedRequest =
            ContentCachingRequestWrapper(request as HttpServletRequest).apply {
                setCharacterEncoding("UTF-8")
            }
        ...
        chain.doFilter(wrappedRequest, wrappedResponse)
        ...
     }
}

그리고 로그를 찍어봤는데 여전히 Body는 비어 있었습니다.

위 ContentCachingRequestWapper 설명을 보면 알 수 있듯이 하나의 전제가 있습니다.

This class acts as an interceptor that only caches content as it is being read but otherwise does not cause content to be read 요청 컨텐츠가 반드시 소비가 되어야 캐싱이 된다.

즉, 소비되지 않은 컨텐츠에 대해서는 캐싱이 되지 않습니다.

저는 요청 바디 로깅을 인터셉터의 preHandle에서 하고 있습니다. @RequestBody 애노테이션에 의해 컨텐츠가 소비되는데 해당 작업은 preHandle 이후에 수행됩니다. 즉, 캐싱되기 전에 요청 로그를 찍게 됩니다.

따라서 요청을 ContentCachingRequestWapper로 감싸도 여전히 Body는 비어 있던 것입니다.

그러면 그냥 Body를 임의로 한 번 읽으면 되는거 아니야?

실제로 그런지 테스트하기 위해서 로그를 찍기 전에 Body를 읽는 작업을 임의로 호출해보고 로그를 찍어봤습니다.

 

override fun preHandle(
    request: HttpServletRequest,
    response: HttpServletResponse,
    handler: Any,
): Boolean {

		...		
		
    request.inputStream.readAllBytes() // Body를 읽는 작업
		
		...
		
		logger.info { 요청 로그 }
}

Body를 읽을 수 있는 것을 볼 수 있죠. 하지만 이렇게 Body를 읽게 되면 실제 데이터를 가져다가 사용하는 곳(ArgumentResolver)에서 읽을 데이터가 사라지기 때문에 에러가 발생하게 됩니다.

[ERROR]: Required request body is missing: ….

 

ArgumentResolver가 사용한 이후에 로그를 찍으면 되잖아?

요청 로그를 ArgumentResolver 이후(정확히는 핸들러 호출 이후) 호출되는 afterComplete에서 찍으면 Body는 소비된 이후이기에 Body를 로그에 남길 수 있습니다.

하지만 요청 로그는 실제 요청을 처리하기 전에 로그를 찍어야 의미가 있다고 생각했습니다. 핸들러 호출 시, 예외가 발생하게 되면 요청 로그 이전에 에러 로그가 찍히게 되어 어떤 요청에 의해 문제가 발생했는지 판단하기 어렵다고 생각했습니다. 따라서 요청 로그는 핸들러 호출 전에 찍고 싶었습니다.

 

커스텀 CachingWrapper

그렇다면 어떻게 요청 바디의 로그를 찍을 수 있을까요?? ContentCachingRequestWapper을 활용할 수 없다면 직접 커스텀 캐싱 클래스를 만들면 됩니다. 서블릿에서는 요청을 개발자가 커스텀 할 수 있게 HttpServletRequestWrapper 를 제공하고 있습니다.

Provides a convenient implementation of the HttpServletRequest interface that can be subclassed by developers wishing to adapt the request to a Servlet.

이를 상속 받는 커스텀 클래스를 만들어서 필터에서 감싸주기만 하면 됩니다.

전 다음 글을 참고해서 아래와 같은 커스텀 클래스를 만들었습니다.

https://sjiwon-dev.tistory.com/27

 

class ReadableRequestWrapper(
    request: HttpServletRequest,
) : HttpServletRequestWrapper(request) {
    private val encoding: Charset
    private val parts: Collection<Part>?
    val contentAsByteArray: ByteArray

    init {
        this.encoding = getEncoding(request.characterEncoding)
        this.parts = getMultipartParts(request)

        try {
            this.contentAsByteArray = request.inputStream.readAllBytes()
        } catch (e: Exception) {
            throw RuntimeException(e)
        }
    }
    ...
}

그리고 필터에서 ContentCachingRequestWrapper 대신 커스텀한 클래스를 감싸 넣어주었습니다.

 

class LoggingWrappingFilter : Filter {
    override fun doFilter(
        request: ServletRequest,
        response: ServletResponse,
        chain: FilterChain,
    ) {
        val wrappedRequest = ReadableRequestWrapper(request as HttpServletRequest)
        ...
        chain.doFilter(wrappedRequest, wrappedResponse)
        ...
     }
}

그러면 에러 발생 없이 요청 로그에 바디가 포함되는 것을 확인할 수 있습니다.

참고

https://coor.tistory.com/49

https://sjiwon-dev.tistory.com/27