Interceptor를 사용하여 Request/Reponse Logging

Interceptor를 사용하여 Request/Reponse Logging 하는 방법에 대해 알아보자

이 글에선 예제 및 테스트용으로 작성하였기에 validation 처리는 따로 하지 않는다.

Interceptor에서 logging을 할 때, Body를 읽지 않는 경우에 발생하는 문제가 있다.

만약 필요하지 않다면 바로 logging을 적용하면된다.

body 사용하지 않는 경우

class ApiLogInterceptor : HandlerInterceptor {
    private val logger = KotlinLogging.logger {}
    override fun preHandle(request: HttpServletRequest, response: HttpServletResponse, handler: Any): Boolean {
        if (handler is HandlerMethod) {
            logger.info { "[Interceptor Request] ${handler.beanType.simpleName}.${handler.method.name} : ${request.method} ${request.requestURI} }
        }
        return true
    }

    override fun afterCompletion(
        request: HttpServletRequest,
        response: HttpServletResponse,
        handler: Any,
        ex: Exception?
    ) {
        if (handler is HandlerMethod) {
            logger.info { "[Interceptor Response] ${handler.beanType.simpleName}.${handler.method.name} : ${response.status} }
        }
    }

}

그러나 Body 의 정보 값이 필요하여 로깅에 넣으려는 경우 logging은 정상 동작하나 controller 에서 body 의 값을 읽을 수 없는 문제가 발생한다.

Interceptor 에서 body 읽은 경우 (Controller 에서 값 읽을 수 없다)

class ApiLogInterceptor : HandlerInterceptor {
    private val logger = KotlinLogging.logger {}
    override fun preHandle(request: HttpServletRequest, response: HttpServletResponse, handler: Any): Boolean {
        if (handler is HandlerMethod) {
            val body = request.inputStream.readAllBytes()
            logger.info { "[Interceptor Request] ${handler.beanType.simpleName}.${handler.method.name} : ${request.method} ${request.requestURI} [Body] : $body" }
        }
        return true
    }

    override fun afterCompletion(
        request: HttpServletRequest,
        response: HttpServletResponse,
        handler: Any,
        ex: Exception?
    ) {
        if (handler is HandlerMethod) {
            val body = response.inputStream.readAllBytes()
            logger.info { "[Interceptor Response] ${handler.beanType.simpleName}.${handler.method.name} : ${response.status} [Body] : $body" }
        }
    }

}

위 코드는 로그는 정상적으로 동작하지만 HttpServletRequest의 InputStream은 개발시에 다시 읽을 수 없도록 되어있어 문제가 발생한다.

Interceptor 에서 Wrapper 적용한 경우 (Controller 에서 값 읽을 수 없다)

class ApiLogInterceptor : HandlerInterceptor {
    private val logger = KotlinLogging.logger {}
    override fun preHandle(request: HttpServletRequest, response: HttpServletResponse, handler: Any): Boolean {
        if (handler is HandlerMethod) {
            val body = getBody(request)
            logger.info { "[Interceptor Request] ${handler.beanType.simpleName}.${handler.method.name} : ${request.method} ${request.requestURI} [Body] : $body" }
        }
        return true
    }

    private fun getBody(request: HttpServletRequest): String {
        val wrapper = ContentCachingRequestWrapper(request)
        return String(wrapper.inputStream.readAllBytes())
    }

    private fun getBody(response: HttpServletResponse): String {
        val wrapper = ContentCachingResponseWrapper(response)
        return String(wrapper.inputStream.readAllBytes())
    }

    override fun afterCompletion(
        request: HttpServletRequest,
        response: HttpServletResponse,
        handler: Any,
        ex: Exception?
    ) {
        if (handler is HandlerMethod) {
            val body = getBody(response)
            logger.info { "[Interceptor Response] ${handler.beanType.simpleName}.${handler.method.name} : ${response.status} [Body] : $body" }
        }
    }

}

이러한 문제를 해결하기 위해 ContentCachingRequestWrapper와 ContentCachingResponseWrapper를 사용하여 cache에 저장하려고 하였으나

위의 코드 또한 같은 문제가 발생하게 된다.

이러한 현상이 발생하는 이유는 다음과 같은 특징에서 나온다.

Servlet Filter는 Java Servlet API의 기능으로 Servlet Container 에서 동작한다.

Spring Interceptor는 Spring Framework에서 제공하는 기능으로, DispatcherServlet 내에서 동작하며 내부에서

interceptor 의 동작을 실행하도록 한것이기 때문에 request 의 객체는 변하지 않게 된다.

(applyPreHandle()를 통해 실행된 preHandle()가 return 으로 객체를 Wrapper 를 반환해주는 것이 아니라 boolean 값 반환)

public class DispatcherServlet extends FrameworkServlet {

    protected void doDispatch(HttpServletRequest request, HttpServletResponse response) throws Exception {

        if (!mappedHandler.applyPreHandle(processedRequest, response)) {
            return;
        }

        // Actually invoke the handler.
        mv = ha.handle(processedRequest, response, mappedHandler.getHandler());

    }
}

이러한 이유로 인하여 filter 에서 wrapping 을 해준뒤 interceptor 에서 처리하도록 수정을 해보자.

@Component
class ApiLogFilter : OncePerRequestFilter() {

    @Throws(ServletException::class, IOException::class)
    override fun doFilterInternal(
        request: HttpServletRequest,
        response: HttpServletResponse,
        filterChain: FilterChain
    ) {
        val wrappingRequest = ContentCachingRequestWrapper(request)
        val wrappingResponse = ContentCachingResponseWrapper(response)
        filterChain.doFilter(wrappingRequest, wrappingResponse)

    }
}

class ApiLogInterceptor : HandlerInterceptor {
    private val logger = KotlinLogging.logger {}
    override fun preHandle(request: HttpServletRequest, response: HttpServletResponse, handler: Any): Boolean {
        if (handler is HandlerMethod) {
            val wrapper = request as ContentCachingRequestWrapper
            val body = String(wrapper.contentAsByteArray)
            logger.info { "[Interceptor Request] ${handler.beanType.simpleName}.${handler.method.name} : ${request.method} ${request.requestURI} [Body] : $body" }
        }
        return true
    }

    override fun afterCompletion(
        request: HttpServletRequest,
        response: HttpServletResponse,
        handler: Any,
        ex: Exception?
    ) {
        if (handler is HandlerMethod) {
            val wrapper = response as ContentCachingResponseWrapper
            val body = String(wrapper.contentAsByteArray)
            logger.info { "[Interceptor Response] ${handler.beanType.simpleName}.${handler.method.name} : ${response.status} [Body] : $body" }
        }
    }

}

이 방법 또한 body 의 값이 빈값("")이 나오게 된다.

그 이유는 ContentCachingRequestWrapper 는 ContentCachingInputStream 을 inner class로 가지며 여기에 input stream을 저장해두었다가 stream을 읽을 때 cachedContent 저장하여 다시 꺼내 쓸 수 있도록 한다.

    private class ContentCachingInputStream extends ServletInputStream {
        @Override
        public int read() throws IOException {
            int ch = this.is.read();
            if (ch != -1 && !this.overflow) {
                if (contentCacheLimit != null && cachedContent.size() == contentCacheLimit) {
                    this.overflow = true;
                    handleContentOverflow(contentCacheLimit);
                }
                else {
                    cachedContent.write(ch);
                }
            }
            return ch;
        }

        @Override
        public int read(byte[] b) throws IOException {
            int count = this.is.read(b);
            writeToCache(b, 0, count);
            return count;
        }

        private void writeToCache(final byte[] b, final int off, int count) {
            if (!this.overflow && count > 0) {
                if (contentCacheLimit != null &&
                        count + cachedContent.size() > contentCacheLimit) {
                    this.overflow = true;
                    cachedContent.write(b, off, contentCacheLimit - cachedContent.size());
                    handleContentOverflow(contentCacheLimit);
                    return;
                }
                cachedContent.write(b, off, count);
            }
        }
    }

이러한 구조로 되어있어 만약 interceptor 에서 request에 있는 input stream 을 꺼내 사용하게 된다면 출력은 정상이지만 위에서 발생했던 현상과 같이 정작 로직에서 body 가 출력되지 않는다.

Interceptor 에서 request body를 포함하려 출력하기 위해서는 preHandle() 가 아닌 afterCompletion()에서 request와 response를 모두 처리해야한다.

class ApiLogInterceptor : HandlerInterceptor {
    private val logger = KotlinLogging.logger {}
    override fun preHandle(request: HttpServletRequest, response: HttpServletResponse, handler: Any): Boolean {
        if (handler is HandlerMethod) {
            request as ContentCachingRequestWrapper
            // body 출력 X
            logger.info { "[Interceptor PRE Handler Request] ${handler.beanType.simpleName}.${handler.method.name} : ${request.method} ${request.requestURI} [Body] : ${String(request.contentAsByteArray)}" }
        }
        return true
    }

    override fun afterCompletion(
        request: HttpServletRequest,
        response: HttpServletResponse,
        handler: Any,
        ex: Exception?
    ) {
        if (handler is HandlerMethod) {
            request as ContentCachingRequestWrapper
            response as ContentCachingResponseWrapper
            logger.info { "[Interceptor Request] ${handler.beanType.simpleName}.${handler.method.name} : ${request.method} ${request.requestURI} [Body] : ${String(request.contentAsByteArray)}" }
            logger.info { "[Interceptor Response] ${handler.beanType.simpleName}.${handler.method.name} : ${response.status} [Body] : ${String(response.contentAsByteArray)}" }
        }
    }
}

모든 요청을 cache에 저장하는건 성능에 영향을 미칠 가능성이 존재하므로 잘 고려해서 사용해야 한다.

test 코드

@SpringBootTest(classes = [KotlinLogApplication::class])
@AutoConfigureMockMvc
class UserApiTest {

    @Autowired
    private lateinit var mockMvc: MockMvc

    @Autowired
    private lateinit var objectMapper: ObjectMapper

    @Test
    fun findAll() {
        mockMvc.perform(MockMvcRequestBuilders.get("/all"))
            .andExpect(MockMvcResultMatchers.status().isOk)
    }

    @Test
    fun signUp() {
        val request = objectMapper.writeValueAsString(SignUpRequest("이름"))
        mockMvc.perform(
            MockMvcRequestBuilders.post("/sign-up").content(request)
                .contentType(MediaType.APPLICATION_JSON).accept(MediaType.APPLICATION_JSON)
        ).andExpect(
            MockMvcResultMatchers.status().isCreated
        )
    }
}

처리 구조

 

https://github.com/hanbong5938/practice/tree/master/logging