BackEnd/Spring

스프링부트 Filter로 요청/응답 정보 로깅 시스템 구축하기

PgmJUN 2024. 12. 19. 17:16

 

 

작업 배경

서버를 운영할 때는 로깅을 통해 서비스 운영에 유용한 매트릭을 흭득할 수 있다.

 

특히 요청/응답 정보 로깅은 실제로 서비스를 운영하면서 버그가 발생했을 때 해당 버그가 어떤 요청에서 비롯되어 어떻게 처리되다가 버그가 발생된 것인지를 쉽게 확인할 수 있도록 만들어준다.

또한 '어떤 요청을 받고 있는지', '적절한 응답을 보내고 있는지', '수상한 요청(Dos, DDos 등)은 없는지', '요청에 소요된 시간이 길진 않은지' 등 유용한 지표를 얻을 수 있다.

 

이렇듯 장점이 명확하기 때문에 요청/응답 정보 로깅은 서버를 개발하는 과정에서 필수적으로 진행해야하는 과정이라고 생각한다.

때문에 오늘은 스프링부트에서 Request/Response 정보를 로깅하는 방법에 대해서 알아볼 것이다.

 

 

AOP 로깅 vs Filter 로깅

그럼 먼저 요청/응답 정보를 무엇을 통해 로깅해야할까?

먼저 떠올랐던 것은 Filter와 AOP가 있었다.

 

AOP 로깅

AOP는 공통관심사를 별도의 모듈로 분리해서 비즈니스 로직에서 반복되는 코드를 제거하여 유지보수성을 높여주는 스프링의 장점 중 하나이다. AOP를 통해 Controller의 RequestMapping 애노테이션을 Pointuct으로 Controller 메서드를 호출했을 때 메서드를 호출한 요청 정보, 그리고 메서드 호출 이후에 응답 정보를 로깅할 수 있다.

 

 

Filter 로깅

필터는 DispatcherServlet이 '동작하기 전'과 '동작한 후' 에서 작동한다.

이러한 특징을 바탕으로 요청과 응답에 대한 정보를 각 시점에 로깅하도록 구현할 수 있다.

 

 

어떤 방식이 적절할까?

둘 다 적용해 본 사람으로서, 구현 방법은 사실 둘 다 구현에 필요한 리소스는 비슷하다고 느꼈다.

 

AOP로 요청 정보에 대한 로깅을 수행한다면 '@RestController 애노테이션이 붙은 클래스의 @RequestMapping 애노테이션이 붙은 메서드' 로 Pointcut을 잡아서, Request 및 Response에 대한 로그를 찍어주면 되고

 

Filter로 로깅을 수행한다면 Filter 인터페이스를 implements 하여, Request 및 Response에 대한 로그를 찍어주도록 구현하면 된다.

 

 

서버 정보를 빼가기 위한 공격성 요청

다만 AOP로 구현하는 경우 존재하지 않는 Endpoint로 들어오는 요청은 로깅할 수 없는 문제가 있었다.

이게 왜 문제인지는 위 이미지를 보면 조금은 이해할 수 있을 것이다.

 

위는 실제 땅콩 서버에 들어온 존재하지 않는 정적 리소스를 조회하려고 시도한 요청의 에러 로그이다.

서버의 중요한 정보가 담겨있는 파일을 조회하여 탈취하기 위해 무작위 Endpoint로 요청을 마구 보내는 일종의 공격성 요청 기록인데 존재하지 않는 Endpoint이기 때문에 HandlerMapping이 수행되지 않고, 그렇기 때문에 컨트롤러의 메서드가 실행되지 않는다.

'누가' '어떤 정보'를 담아서 요청을 보낸 것인지 정확한 모니터링이 되지 않았다.

 

때문에 이번 프로젝트에는 DispatcherServlet에 요청이 도달하기 전 요청 정보, 그리고 요청이 처리된 후 응답 정보를 모두 로깅할 수 있는 'Filter 방식'을 통해 서버로 들어오는 모든 요청에 대해서 로깅 시스템을 구축해보고자 한다.

물론 Filter로 로깅하는 것뿐만 아니라, 존재하는 API 이외의 요청은 서버에서 받지 않도록 별도의 처리를 해주어야 한다고도 생각한다. 이에 대한 자세한 내용은 여기에서 확인할 수 있다.

 

 

Filter란?

jakarta.servlet.Filter

Filter는 스프링 컨테이너의 DispatcherServlet에 요청이 도달하기 전 그리고 DispatcherServlet에서 요청이 처리된 이후 시점에 존재하는 요청 사후/사전 처리 작업 객체이다.

servlet 패키지에 포함되어 있는 필터는 Filter 인터페이스를 implements 하여 직접 구현할 수 있다.

 

Filter 인터페이스에 들어가보면 위와 같이 설명이 되어있는데 요청/응답에 대한 로깅 필터로도 사용하는 것이 적절한 사용 방식들 중 하나임을 알 수 있다.

 

Filter의 메서드

init()

default void init(FilterConfig filterConfig) throws ServletException

Filter가 정상적으로 서비스에 배치되고 있음을 나타내기 위해 웹 컨테이너에 의해 호출되는 메서드

서블릿 컨테이너는 Filter를 인스턴스화한 후 init() 메소드를 정확히 한 번 호출한다.

init 메소드가 성공적으로 완료되어야 Filter가 Filtering 작업을 수행하도록 요청할 수 있다.

 


destroy()

default void destroy()

doFilter() 메소드 내의 모든 스레드가 종료되거나 제한 시간이 경과한 후에 로직이 종료되었음을 알리기 위해 호출되는 메서드

doFilter

 

 

doFIlter()

void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)
        throws IOException, ServletException;

유저가 서버 리소스를 흭득하기 위해 보낸 요청으로 인해 요청/응답 정보 쌍이 FilterChain을 통해 전달될 때마다 컨테이너에 의해 호출되는 메서드

ServletRequest, ServletResposne 를 통해 응답 요청 정보를 활용할 수 있으며, FilterChain 매개변수를 통해 체인의 다음 엔티티로 요청/응답 정보를 전달할 수 있다.

 

 

 

적용 방법

Filter를 통해 적용해보는 과정에서 몇 가지 시행착오를 겪고 이에 대한 과정과 결론을 정리해보고자 한다.

 

1. Request Body 정보 캐싱 처리

@Throws(IOException::class, ServletException::class)
override fun doFilter(servletRequest: ServletRequest, servletResponse: ServletResponse, filterChain: FilterChain) {
}

위 코드는 Filter에서 로깅에 사용할 수 있는 doFilter() 메서드이다.

ServletRequest를 통해 요청 정보를 로깅할 수 있는데 이때 요청 정보는 InputStream 형태로 들어오며 Stream은 단 한 번만 읽을 수 있다.

 

때문에 InputStream을 로깅 시점, 요청 정보 사용 시점에서 모두 사용하려면 캐싱 처리를 수행해야한다.

캐싱으로 인해 추가적인 메모리를 사용하게 되지만 요청이 거의 없는 현재 프로젝트 구조에서는 나쁘지 않은 선택이라고 생각한다.

어떻게 캐싱하는 것이 좋았을까?

 

고민1 - ContentCachingRequestWrapper, ContentCachingResponseWrapper

첫 번째 방법으로 Spring에서 제공하는 ContentCachingWrapper를 고민해보게 되었다.

Filter 로깅과 관련해서 찾아보면 주로 나오는 것이 ContentCachingRequestWrapper이다.

해당 객체는 HttpServletRequest 정보를 Wrapper 패턴으로 감싸고, InputStream 값을 캐싱하여 여러 번 사용할 수 있도록 만들어주는 유용한 도구이다.

 

 

ContentCachingWrapper의 문제점

 

하지만 해당 방식에는 문제가 하나 있었다.

요청 정보에 대한 InputStream을 ContentCachingWrapper에 담는다고 캐싱이 끝이 아니었다.

 

ContentCachingWrapper를 사용하면 Stream의 값이 캐싱되어 맘껏 값을 사용해도 된다고 생각했는데,

그게 아니라 해당 InputStream을 읽으면 해당 내용이 클래스 내부 필드인 cachedContent에 캐싱되는 구조였다.

 

이 이후부터는 getContentAsByteArray() 메서드를 통해 캐시된 Stream 값을 사용할 수 있는 구조이다.

결국 로깅하고 싶은 요청/응답 정보가 각자 원래 사용되던 곳에서 한 번은 읽힌 뒤에야 캐싱된 값을 사용할 수 있게 되는 것이다.

 

Stream은 1회성인데 Filter에서 읽어버리면 위와 같이 로깅은 성공하지만 Controller에서는 HttpMessageNotReadableException 예외가 발생하면서 사용할 수 없게 된다. (Controller에서 getContentAsByteArray() 메서드를 사용하진 않으니까)

 

결국 이렇게 요청에 대한 처리가 모두 끝난 뒤에 요청/응답에 대한 로깅을 남길 수 밖에 없다.

하지만 나는 요청/응답 로깅을 요청이 들어온 순서에 맞게 순차적으로 기록하는 것이 가독성에 더 좋겠다 싶어서 다른 방법을 고민해보았다.

 

 

고민2 - 커스텀 Request Body 캐싱 객체 구현하기 ✅

다음 대안으로 찾은 방식은 커스텀으로 Request Body를 캐싱하는 객체를 구현하는 방법이다.

 

 

CachedBodyHttpServletRequest 구현

import jakarta.servlet.ReadListener
import jakarta.servlet.ServletInputStream
import jakarta.servlet.http.HttpServletRequest
import jakarta.servlet.http.HttpServletRequestWrapper
import java.io.ByteArrayInputStream
import java.io.IOException

class CachedBodyHttpServletRequest(request: HttpServletRequest) : HttpServletRequestWrapper(request) {

    private val cachedBody: ByteArray

    init {
        cachedBody = request.inputStream.readAllBytes()
    }

    @Throws(IOException::class)
    override fun getInputStream(): ServletInputStream {
        return object : ServletInputStream() {
            private val byteArrayInputStream = ByteArrayInputStream(cachedBody)

            override fun read(): Int {
                return byteArrayInputStream.read()
            }

            override fun isFinished(): Boolean {
                return byteArrayInputStream.available() <= 0
            }

            override fun isReady(): Boolean {
                return true
            }

            override fun setReadListener(listener: ReadListener?) {
                // 비동기 처리가 필요하다면 구현을 추가
            }
        }
    }

    fun getBody(): String {
        return String(cachedBody, Charsets.UTF_8)
    }
}

이 코드는 ContentCachingWrapper 의 문제를 해결하기 위해 직접 구현한 객체이다.

ContentCachingWrapper와 동일하게 HttpServletRequestWrapper를 상속받아 구현하였기에 대체로 사용할 수 있다.

 

해당 객체의 특징

  • 객체의 인스턴스가 생성되는 시점에 'init 블럭'을 통해서 cachedBody에 InputStream의 byte 값을 모두 캐싱해버린다.
  • getInputStream() 메서드를 override 하여, 해당 메서드 호출 시 항상 캐싱해둔 byte 값을 통해 ServletInputStream 객체를 만들어 return 한다.

 

이를 통해 InputStream을 담아서 인스턴스를 생성하면 그 시점부터 항상 캐싱된 cachedBody 값을 사용할 수 있게 되었다.

때문에 컨트롤러에서 getInputStream() 메서드를 한 번 호출 하고, 그 이후에 getContentAsByteArray() 를 통해 캐싱된 body값을 얻을 수 있는 ContentCachingWrapper보다 활용도가 높아졌다.

결론적으로 해당 커스텀 객체를 만든 캐싱 방식을 채택하게 되었다.

 

 

2. 요청정보 로깅 Filter 구현하기

import com.whatcampus.whatcampus.logger
import jakarta.servlet.*
import jakarta.servlet.http.HttpServletRequest
import jakarta.servlet.http.HttpServletResponse
import org.slf4j.MDC
import org.springframework.core.annotation.Order
import org.springframework.stereotype.Component
import java.io.IOException
import java.util.*

private val X_FORWARDED_FOR_HEADER = "X-Forwarded-For"
private val TRACE_ID = "traceId"

@Component
@Order(1)
class RequestLoggingFilter : Filter {

    val log = logger()

    @Throws(IOException::class, ServletException::class)
    override fun doFilter(servletRequest: ServletRequest, servletResponse: ServletResponse, filterChain: FilterChain) {
        val request = CachedBodyHttpServletRequest(servletRequest as HttpServletRequest)
        val response = servletResponse as HttpServletResponse
        MDC.put(TRACE_ID, UUID.randomUUID().toString())

        val requestLine = "${request.method} ${request.requestURI}${getRequestParams(request)}"
        log.info("Request (${getRequestAddr(request)}) : $requestLine ${request.getBody()}")
        filterChain.doFilter(request, response)
        log.info("Response : $requestLine : ${response.status}")
    }

    fun getRequestAddr(request: HttpServletRequest): String {
        val requestAddr = request.getHeader(X_FORWARDED_FOR_HEADER)
        return requestAddr ?: request.remoteAddr
    }

    fun getRequestParams(request: HttpServletRequest): String {
        var queryParameters = request.parameterMap
            .entries
            .joinToString("&") { (key, values) -> "$key=${values[0]}" }

        if (queryParameters.isNotEmpty()) {
            queryParameters = "?$queryParameters"
        }
        return queryParameters
    }
}

 

위에서 구현한 CachedBodyHttpServletRequest 를 바탕으로 구현된 요청 응답 정보 로깅 Filter이다.

 

FilterChain에 Filter 등록

@Component
@Order(1)
class RequestLoggingFilter : Filter {
  • @Component 애노테이션을 선언해주면 컴포넌트 스캔에 의해 Bean으로 등록된다.
    • Bean으로 등록된 Filter 타입 객체는 Spring Boot AutoConfiguration에 의해 자동으로 FilterChain에 추가된다.
  • @Order 애노테이션과 order 매개변수 값을를 입력해줌으로써 FilterChain에서 몇 번째 순서로 동작할 지를 정의할 수 있다.
    • order를 1로 설정해주었기 때문에 가장 앞단에서 RequestLoggingFilter는 동작하는 필터가 되었다.

 

 

doFilter()

@Throws(IOException::class, ServletException::class)
override fun doFilter(servletRequest: ServletRequest, servletResponse: ServletResponse, filterChain: FilterChain) {
    val request = CachedBodyHttpServletRequest(servletRequest as HttpServletRequest)
    val response = servletResponse as HttpServletResponse
    MDC.put(TRACE_ID, UUID.randomUUID().toString())

    val requestLine = "${request.method} ${request.requestURI}${getRequestParams(request)}"
    log.info("Request (${getRequestAddr(request)}) : $requestLine ${request.getBody()}")
    filterChain.doFilter(request, response)
    log.info("Response : $requestLine : ${response.status}")
}
  1. 요청 정보를 HttpServletRequest로 캐스팅하여 CachedBodyHttpServletRequest에 담는다.
  2. 응답 정보를 HttpServletResponse로 캐스팅한다.
    • 이렇게 캐스팅하는 이유는 ServletRequest/ServletResponse 에서는 로깅에 필요한 정보를 얻을 수 없기 때문이다.
  3. MDC에 요청 추적을 위한 TraceId를 등록한다. (자세히 알고 싶으면 여기 클릭)
  4. 요청 정보 로깅 -> 다음 필터 호출 및 요청 처리 -> 응답 정보 로깅
    • [Request 로그 형태 예시] Request (IP주소) : GET /api/v1/test?key=value { "key":"value"}
    • [Response 로그 형태 예시] Response : GET /api/v1/test?key=value : 200

 

getRequestAddr()

fun getRequestAddr(request: HttpServletRequest): String {
    val requestAddr = request.getHeader(X_FORWARDED_FOR_HEADER)
    return requestAddr ?: request.remoteAddr
}
  1. 로그에 남길 요청을 보낸 주소를 흭득한다.
    • WAS 앞단에 구현해둔 Nginx 리버스 프록시 서버에서 요청을 먼저 받고 'X_FORWARDED_FOR' 헤더로 WAS에 실제 요청 주소를 전달하도록 설정해놓은 상태이기 때문에, X_FORWARED_FOR 헤더가 존재한다면 그 값으로 로깅한다.

 

getRequestParams()

fun getRequestParams(request: HttpServletRequest): String {
    var queryParameters = request.parameterMap
        .entries
        .joinToString("&") { (key, values) -> "$key=${values[0]}" }

    if (queryParameters.isNotEmpty()) {
        queryParameters = "?$queryParameters"
    }
    return queryParameters
}
  1. 요청에 포함된 쿼리 파라미터 값을 파싱하여 "?key1=value1&key2=value2" 형태로 문자열을 만든다.

 

3. 결과 확인

Request 로그

Request 로그

[Request 로그 형태 예시] Request (IP주소) : GET /api/v1/test?key=value { "key":"value"}

 

 

Response 로그

Response 로그

[Response 로그 형태 예시] Response : GET /api/v1/test?key=value : 200

 

 

커스텀 Logger를 통해 최종적으로 출력된 로그

Filter에서 함께 설정했던 TraceId 값과 함께 요청/응답 로그가 잘 출력되는 것을 확인할 수 있다.

 

 

결론

오늘은 Filter를 통한 스프링부트 요청/응답 정보 로깅 시스템 구축하기에 대해서 알아보았다.

 

위에서 말했듯이 AOP를 통해 로깅 시스템을 구축하는 것과 난이도에 큰 차이는 없었던 것 같다.

존재하는 약간의 차이는 '존재하지 않는 HTTP API 메서드에 대한 요청이더라도 로그를 남기느냐 아니냐' 인 것 같다.

AOP로도 구현하려면 할 수 있겠지만 그렇게 할 거면 그냥 Filter를 쓰면 될 것 같다.

 

다음에는 땅콩에서 적용해보았던 AOP를 통한 요청/응답 정보 로깅 방식도 작성하여 공유해겠다.

 

 

저작자표시