[Spring Boot] 스프링 인터셉터(Spring Interceptor)를 활용해서 API 로그를 DB에 기록해보자

목차

들어가기 전에

이전 포스트에서 AOP를 사용해서 API 로그를 기록하는 내용을 다뤘는데 이런 이야기를 들었다.

사실 지금까지 프로젝트를 진행하는 동안 인터셉터를 구현해서 사용했던 적이 없다보니 컨트롤러들에 공통으로 적용하는 로직은 익숙한 AOP로 구현했다. 그런데 인터셉터도 어쨌든 요청과 응답을 가로채서 일련의 행동을 수행하니까 인터셉터로 구현하는 것도 괜찮겠다는 생각이 들었다.

 

그래서 이번에는 스프링 인터셉터를 활용해서 API 로그를 기록해보려고 한다.

스프링 인터셉터는 어떻게 구성되는가?

스프링 인터셉터는 보통 HandlerInterceptor를 구현하는 별도의 클래스를 작성해서 구현한다.

HandlerInterceptorAdapter를 상속받는 방법은 스프링부트 2.4(스프링 5.3)부터 Deprecated 되었으며, 스프링부트 3.x(스프링 6.x)에서는 아예 삭제되었기 때문에 이 글에서는 HandlerInterceptor만 다룬다.

HandlerInterceptor는 위와 같이 preHandle(), postHandle(), afterCompletion()이라는 3개의 메소드가 있는데 이들이 호출되는 시점은 다음과 같다.

• preHandle() : 실제 핸들러가 실행되기 이전
• postHandle() : 핸들러가 실행된 이후
• afterCompletion() : 요청이 모두 완료된 이후

preHandle()은 다른 메소드와 달리 boolean타입의 반환값을 갖는데, true인 경우에는 요청을 마저 실행하고 false인 경우에는 요청을 중단한다.

 

여기서 postHandle()과 afterCompletion()의 호출 시점이 모호할 수 있다.

 

postHandle()은 핸들러가 실행된 이후(= 결과값이 반환된 이후)에 실행되기 때문에 예외가 발생하여 return에 도달하지 못했을 때는 실행되지 않는다.

 

반면에 afterCompletion()은 말 그대로 요청이 모두 완료된 이후, 즉 예외 발생여부와 관계 없이 클라이언트에 응답이 전달될 때 실행된다고 이해하면 될 것 같다.

 

로그를 API 요청이 들어올 때, 예외와 상관 없이 응답이 나갈 때 기록할 것이기 때문에 preHandle()과 afterCompletion()을 재정의할 것이다.

로그 엔티티와 레포지토리 구성

로그 엔티티

로그 엔티티의 구성은 이전글에서 사용한 엔티티를 거의 그대로 사용했다.

@Entity
class ApiLog(
    @Id
    @GeneratedValue(strategy = GenerationType.IDENTITY)
    val seq: Long? = null,
    @Column(unique = true)
    val requestId: UUID,
    val serverIp: String,
    @Column(length = 4096)
    val requestUrl: String,
    val requestMethod: String,
    var responseStatus: Int? = null,
    val clientIp: String,
    @Column(length = 4096)
    val request: String,
    @Column(length = 4096)
    var response: String? = null,
    val requestTime: LocalDateTime = LocalDateTime.now(),
    var responseTime: LocalDateTime?= null
)

다만 스프링 인터셉터는 하나의 메소드 내에서 처리가 가능했던 AOP와 달리 요청이 들어가기 전과 요청이 완료된 후로 메소드가 나뉘기 때문에 UUID 타입의 요청 ID를 추가하여 고유키로 설정했다.

로그 레포지토리

interface ApiLogRepository : JpaRepository<ApiLog, Long> {
    @Transactional
    @Modifying
    @Query("""
        UPDATE ApiLog a
        SET a.responseStatus = :status, a.response = :response, a.responseTime = CURRENT_TIMESTAMP
        WHERE a.requestId = :requestId
    """)
    fun updateResponse(requestId: UUID, status: Int, response: String)
}

레포지토리도 크게 다르지 않다. 변경된 설계에 맞춰서 UPDATE 쿼리의 WHERE 조건을 seq에서 requestId로 변경만 해줬다.

RequestBody와 ResponseBody를 기록하려면 사전 준비가 필요하다!

그런데 무작정 로그를 기록하는 인터셉터를 작성하고 테스트 코드를 실행했더니 바로 테스트가 실패하는 것을 볼 수 있었다.

이는 인터셉터 메소드들의 파라미터인 HttpServletRequest와 HttpServletResponse의 문제였는데, 이 두가지 타입에서 body를 받아오려면 각각 getReader()와 getWriter()를 통해 읽어와야 하고 이 방식은 스트림을 사용하게 된다.

 

문제는 핸들러(컨트롤러)에서 @RequestBody로 RequestBody를 읽을 때나 @ResponseBody를 붙여서 ResponseBody를 반환할 때도 스트림을 사용한다는 점이다.

 

preHandle()과 afterCompletion()이 호출되는 순서

preHandle()과 afterCompletion()이 호출되는 순서를 나타낸 대략적으로 보면 핸들러에 요청이 들어가기 전에 preHandle()이 요청을 가로채고, 핸들러에서 응답값을 반환하면 서블릿 컨테이너에서 처리한 후 afterCompletion()이 호출되는 구조이다.

 

자바의 입출력 스트림은 한번 읽은 내용을 다시 읽을 수 없다. 다시 말해 preHandle()에서 로그를 기록하기 위해 RequestBody를 읽으면 핸들러는 이미 내용을 모두 읽어버린 스트림만 전달되어 요청을 처리할 수 없다. 또한, afterCompletion()에서는 이미 서블릿 컨테이너에서 ResponseBody를 모두 읽어버렸기 때문에 로그를 기록할 수 없게 된다.

preHandle()에서 RequestBody를 읽어버리면 이미 getReader()가 호출되었다면서 예외가 발생해버린다.

afterCompletion()에서 ResponseBody를 읽으려고 하면 이미 getOutputStream()이 호출되었다면서 예외가 발생해버린다.

Wrapper 클래스로 요청과 응답을 감싸주자!

요청 스트림과 응답 스트림을 한 번만 읽을 수 있는 점이 문제니까 스트림을 복사해서 사용하면 두번 읽지 못하는 문제를 해결할 수 있을것이다.

 

다만, 인터셉터에서는 HttpServletRequest와 HttpServletResponse를 변경할 수 없기 때문에 필터에서 이를 처리해줘야 한다.

 

ResponseBody의 경우에는 스프링에 ContentCachingResponseWrapper라는 클래스가 있기 때문에 해당 클래스로 감싸준 후 copyBodyToResponse()를 사용해서 body 값을 복사해주면 된다.

 

RequestBody는 별도로 Wrapper 클래스를 구현해줘야 한다. 요청을 감싸는 ContentCachingRequestWrapper 클래스가 있긴 하지만 이 클래스는 body를 request에 복사해주는 메소드가 별도로 존재하지 않고, 일단 RequestBody를 한번 읽어야 캐싱되기 때문에 아직 RequestBody가 읽히지 않은 preHandle()에서는 사용할 수 없기 때문이다.

 

아래와 같이 OncePerRequestFilter를 상속받는 커스텀 필터를 작성한다.

@Component
class LoggingFilter : OncePerRequestFilter() {
    override fun doFilterInternal(request: HttpServletRequest, response: HttpServletResponse, filterChain: FilterChain) {
        val requestWrapper = MultipleReadableRequestWrapper(request)
        val responseWrapper = ContentCachingResponseWrapper(response)
        filterChain.doFilter(requestWrapper, responseWrapper)
        responseWrapper.copyBodyToResponse()
    }
}

OncePerRequestFilter는 스프링에서 제공하는 추상 클래스로, 각 요청당 반드시 한번만 실행되는 필터라고 볼 수 있다. 스프링 빈으로 등록하기만 하면 동작하고, 별도의 설정이 필요하지 않기 때문에 간단한 처리를 위한 필터를 추가할 때 적합하다.

 

ContentCachingResponseWrapper로 감싸준 응답값은 반드시 copyBodyToResponse()로 응답값을 감싸줘야 클라이언트가 정상적으로 결과를 전달받을 수 있다.

커스텀 RequestWrapper 클래스 작성

RequestBody를 여러번 읽을 수 있게 해주는 HttpServletRequestWrapper를 상속받는 커스텀 클래스를 작성해보자.

class MultipleReadableRequestWrapper(request: HttpServletRequest) : HttpServletRequestWrapper(request) {
    private val outputStream = ByteArrayOutputStream()
    
    val contents get() = inputStream.use { it.readBytes() }

    override fun getInputStream(): ServletInputStream {
        IOUtils.copy(super.getInputStream(), outputStream)
        return object : ServletInputStream() {
            private val buffer = outputStream.toByteArray().inputStream()
            override fun read() = buffer.read()
            override fun isFinished() = buffer.available() == 0
            override fun isReady() = true
            override fun setReadListener(listener: ReadListener?) {}
        }
    }
}

기존 입력 스트림의 내용을 복사할 ByteArrayOutputStream을 프로퍼티로 선언하고 getInputStream()을 재정의한다.

 

입력 스트림을 여러 번 읽을 수 있도록 getInputStream()에서 기존의 입력 스트림 내용을 복사하고 복사된 스트림을 토대로 내용을 읽을 수 있는 ServletInputStream 객체를 반환한다. ServletInputStream이 추상 클래스이기 때문에 익명 클래스 객체를 반환하도록 했다.

 

그 외에 입력 스트림의 내용을 읽는 contents라는 프로퍼티를 추가하여 RequestBody를 얻을 수 있게 해준다.

사전 준비가 끝났으니 인터셉터를 구현하자!

이제 HandlerInterceptor를 구현해서 preHandle()과 afterCompletion()을 재정의해보자.

@Component
class LoggingInterceptor(private val apiLogRepository: ApiLogRepository) : HandlerInterceptor {
    private val objectMapper = ObjectMapper()

    override fun preHandle(request: HttpServletRequest, response: HttpServletResponse, handler: Any): Boolean {
        if (handler !is HandlerMethod) return true
        val requestWrapper = request as MultipleReadableRequestWrapper
        val requestParams = request.parameterMap.map { (key, value) -> "$key=${value.contentToString()}" }.joinToString(", ")
        val requestBody = objectMapper.readTree(requestWrapper.contents.toString(Charsets.UTF_8))
        val requestId = UUID.randomUUID()
        request.setAttribute("requestId", requestId)
        apiLogRepository.save(
            ApiLog(
                requestId = requestId,
                serverIp = InetAddress.getLocalHost().hostAddress,
                requestUrl = request.requestURL.toString(),
                requestMethod = request.method,
                clientIp = request.getHeader("X-Forwarded-For")?.takeIf { it.isNotBlank() } ?: request.remoteAddr,
                request = if (requestParams.isNotBlank()) "$requestParams, $requestBody" else "$requestBody"
            )
        )
        return true
    }

    override fun afterCompletion(request: HttpServletRequest, response: HttpServletResponse, handler: Any, ex: Exception?) {
        if (handler !is HandlerMethod) return
        val responseWrapper = if (response is ContentCachingResponseWrapper) response else ContentCachingResponseWrapper(response)
        val requestId = request.getAttribute("requestId") as UUID
        apiLogRepository.updateResponse(requestId, response.status, responseWrapper.contentAsByteArray.toString(Charsets.UTF_8))
    }
}

우선 API 요청일 때만 로그를 기록할 것이기 때문에 preHandle()과 afterCompletion() 모두 handler의 타입이 HandlerMethod가 아닌 경우에는 바로 true를 반환한다.

 

preHandle()은 로그 엔티티 객체를 생성하여 저장하기 위한 일련의 절차를 수행한다. request는 필터에서 감싸줬던 MultipleReadableRequestWrapper로 형변환 해주고 contents를 통해 RequestBody를 얻을 수 있다.

 

여기서 RequestBody에 담기는 JSON 데이터에는 클라이언트가 보낸 JSON의 포맷이 그대로 담겨있다. 위 예제 코드에서는 RequestBody의 포맷을 컴팩트 JSON으로 통일하기 위해 RequestBody를 JsonNode로 변환해서 기록하긴 했지만, 로그에 기록되는 JSON의 포맷을 딱히 신경쓰지 않을 거라면 굳이 ObjectMapper를 사용할 필요는 없다.

 

이후 동일한 요청인지 확인하기 위해 랜덤한 UUID를 생성하여 request에 추가한다. 이 값은 이후 afterCompletion()에서 요청 로그 데이터에 응답 데이터를 업데이트할 때 사용할 것이다.

 

afterCompletion()에서는 response를 ContentCachingResponseWrapper로 형변환해준다. 이후 preHandle()에서 request에 추가했던 requestId를 가져와서 해당 requestId를 가진 로그 데이터의 응답 관련 컬럼들을 업데이트 해주면 된다.

 

afterCompletion()은 응답 처리가 끝난 이후에 호출되기 때문에 AOP에서 ExceptionHandler가 예외를 전역처리를 할 수 있도록 별도로 처리해야 했던 절차 없이 바로 응답 관련 데이터만 사용하면 된다.

스프링에 인터셉터를 등록

이제 인터셉터를 등록해주면 마무리된다.

@Configuration
class WebMvcConfig(private val loggingInterceptor: LoggingInterceptor) : WebMvcConfigurer {
    override fun addInterceptors(registry: InterceptorRegistry) {
        registry.addInterceptor(loggingInterceptor)
    }
}

이 글에서는 DB를 사용하기 위해 인터셉터를 스프링 빈으로 등록했기 때문에 의존성 주입을 받아서 사용했지만 인터셉터를 굳이 스프링 빈으로 등록할 필요가 없다면 그냥 생성자를 통해 인터셉터 객체를 추가해주면 된다.

 

registry.addInterceptors()는 AddInterceptor 객체를 반환하는데 이 객체에서 addPathPatterns() 메소드로 인터셉터를 적용할 URI 패턴을 설정할 수 있고, excludePathPatterns() 메소드로 인터셉터를 제외할 URI 패턴을 설정할 수도 있다.

 

위 코드처럼 addPathPatterns()를 사용하지 않는다면 모든 URI 패턴에 인터셉터가 적용된다.

이제 테스트 코드도 통과하고 DB에도 로그가 잘 기록되면서 응답이 제대로 나오는 것을 확인할 수 있다.

마치며

스프링 인터셉터와 스프링 AOP 모두 공통 로직을 처리하기 좋은 방법이라고 생각한다. AOP는 대상이 되는 메소드의 전반적인 정보를 쉽게 얻을 수 있기 때문에 조금 더 세부적인 공통 로직을 처리하기 좋고 인터셉터는 웹 요청 기반이기 때문에 로그 기록이나 권한 검증 같이 웹 요청 및 응답과 관련된 공통 로직을 처리하기 좋다고 생각한다.

 

RequestBody와 ResponseBody를 기록하려면 별도로 필터와 Wrapper 클래스를 작성해야 하는 점이 조금 귀찮았지만 @ExceptionHandler를 사용한 전역 예외처리 결과를 추가 설정 없이 기록할 수 있다는 점에서 오히려 AOP를 활용한 방식보다 더 편하게 구현할 수 있었다고 생각한다.

 

포스트에서 사용된 코드의 전체 코드는 Github에서 확인할 수 있다.

참조링크

Interception :: Spring Framework

[Spring Boot] Request body, Response body 로깅 하는 법 (with 코틀린)

ContentCachingResponseWrapper Produces Empty Response