로그 한 줄에 요청과 응답을 다 담았다 — ONELINE 구조화 로깅

2025년 12월 18일 — LoggingFilter 최초 구현 2025년 12월 19일 — 헬스체크 로깅 제외 처리 2026년 2월 27일 — trace_id, span_id 통합

문제: 로그가 흩어져 있어서 추적이 안 된다

Spring Boot 기본 로깅은 이런 식이다.

2025-12-18 10:32:15 INFO  - POST /api/payments
2025-12-18 10:32:15 DEBUG - Request body: {"amount": 10000}
2025-12-18 10:32:16 INFO  - Payment completed
2025-12-18 10:32:16 DEBUG - Response: {"status": "COMPLETED"}

문제:

요청과 응답이 여러 줄에 나뉘어서, 동시 요청이 오면 어떤 요청의 어떤 응답인지 알 수 없다
응답 시간이 안 보인다
JSON이 아니라 로그 수집기에서 파싱하기 어렵다

해결: 요청-응답을 한 줄 JSON으로

OncePerRequestFilter를 상속한 LoggingFilter를 만들어서, 모든 API 요청을 하나의 JSON 라인으로 기록하도록 했다. → OncePerRequestFilter는 Spring이 제공하는 필터로, HTTP 요청 하나당 딱 한 번만 실행되는 것을 보장한다. 포워딩 등으로 같은 요청이 여러 번 필터를 거치는 것을 방지한다.

@Component
@Order(1)
class LoggingFilter(private val requestBean: RequestBean) : OncePerRequestFilter() {
    private val mapper: ObjectMapper = ObjectMapper()

    override fun doFilterInternal(
        request: HttpServletRequest,
        response: HttpServletResponse,
        filterChain: FilterChain
    ) {
        val requestWrapper = ContentCachingRequestWrapper(request)
        val responseWrapper = ContentCachingResponseWrapper(response)

        MDC.put("apiId", requestBean.apiId) // → MDC(Mapped Diagnostic Context)는 스레드별로 로그에 추가 정보를 넣는 저장소다

        try {
            // 클라이언트 정보 수집
            val clientIp = requestWrapper.getHeader("X-REAL-IP") ?: requestWrapper.remoteAddr
            requestBean.setAppInfo(osInfo, deviceInfo, appVersion, clientIp)

            filterChain.doFilter(requestWrapper, responseWrapper)
        } finally {
            if (!isExcludedPath(requestWrapper.requestURI)) {
                onelineLogging(requestBean.getElapsedTime(), requestWrapper, responseWrapper)
            }
            MDC.clear()
        }
        responseWrapper.copyBodyToResponse()
    }
}

핵심은 ContentCachingRequestWrapper / ContentCachingResponseWrapper다. Spring이 제공하는 이 래퍼를 쓰면 요청/응답 바디를 읽어도 스트림이 소비되지 않는다. → HTTP 요청의 바디는 기본적으로 InputStream(입력 스트림)이라 한 번 읽으면 사라진다. 이 래퍼는 읽은 내용을 내부에 캐시해두어서 여러 번 읽을 수 있게 해준다. 이게 없으면 로깅할 때 바디를 읽고 나면 컨트롤러에서 또 읽을 수 없어서 에러가 난다.

ONELINE 로그 포맷

private fun onelineLogging(msTime: Int, request: ContentCachingRequestWrapper, response: ContentCachingResponseWrapper) {
    val reqRes = ReqRes(
        msTime,
        request.requestURI,
        request.queryString,
        parseJson(request.contentAsString),
        parseJson(String(response.contentAsByteArray, StandardCharsets.UTF_8)),
        request.method,
        response.status,
        headerMap(request),
        headerMap(response),
        traceId = MDC.get("trace_id"),
        spanId = MDC.get("span_id")
    )
    logger.info("[ONELINE] ${mapper.writeValueAsString(reqRes)}")
}

실제로 찍히는 로그:

[ONELINE] {"msTime":1234,"uri":"/api/payments","method":"POST","statusCode":200,"reqBody":{"amount":10000,"merchantId":"M001"},"resBody":{"status":"COMPLETED","txHash":"0xabc..."},"traceId":"abc123","spanId":"def456"}

이 한 줄에:

응답 시간 (msTime)
URI, HTTP 메서드
요청/응답 바디
HTTP 상태 코드
요청/응답 헤더
OpenTelemetry trace_id, span_id

전부 들어가 있다. 로그 수집기에서 JSON 파싱 한 번이면 원하는 필드를 뽑을 수 있다.

RequestBean: 요청 단위 컨텍스트 관리

@Component
@Scope(value = WebApplicationContext.SCOPE_REQUEST, proxyMode = ScopedProxyMode.TARGET_CLASS)
class RequestBean(
    var clientIp: String = "",
    var osInfo: String? = null,
    var deviceInfo: String? = null,
    var appVersion: String? = null,
    val apiId: String = UUID.randomUUID().toString(),
) {
    private val stopWatch = StopWatch()

    init {
        stopWatch.start()
    }

    fun getElapsedTime(): Int {
        stopWatch.stop()
        val totalTimeMillis = stopWatch.totalTimeMillis
        stopWatch.start()
        return totalTimeMillis.toInt()
    }
}

SCOPE_REQUEST 빈이라 HTTP 요청마다 새로 생성된다. → SCOPE_REQUEST는 Spring 빈의 생명주기를 HTTP 요청 단위로 관리하겠다는 설정이다. 일반 빈은 애플리케이션 전체에서 하나지만, 요청 스코프 빈은 요청마다 새로 만들어지고 요청이 끝나면 사라진다. 생성 시 StopWatch가 자동 시작되므로, 응답 시점에 getElapsedTime()을 호출하면 정확한 처리 시간이 나온다.

apiId는 UUID로 생성해서, 같은 요청의 로그들을 묶는 상관관계 ID(Correlation ID) 역할을 한다. → 상관관계 ID란 하나의 요청에서 발생하는 여러 로그를 하나로 묶어 추적할 수 있게 해주는 고유 식별자다.

불필요한 로그 제외

헬스체크, Swagger, Actuator 같은 경로는 매초마다 호출되는데 로그를 남기면 의미 없는 노이즈만 쌓인다. → 헬스체크는 서버가 살아있는지 주기적으로 확인하는 요청이다. Actuator는 Spring Boot 애플리케이션의 상태 정보를 노출하는 모듈이다.

private fun isExcludedPath(uri: String): Boolean {
    return uri.startsWith("/swagger-ui") ||
            uri.startsWith("/v3/api-docs") ||
            uri.startsWith("/h2-console") ||
            uri.contains("/actuator") ||
            uri.contains("/health")
}

이걸 안 넣었다가 로그 파일이 헬스체크로 가득 찬 적이 있다. 2025년 12월 19일에 급하게 추가했다.

parseJson: 안전한 JSON 파싱

private fun parseJson(str: String?): Any? {
    if (str.isNullOrBlank()) return null
    return try {
        mapper.readValue(str, Any::class.java)
    } catch (e: Exception) {
        str  // JSON이 아니면 문자열 그대로 반환
    }
}

요청/응답 바디가 항상 JSON은 아니다. 파일 업로드나 plain text 응답도 있으니, 파싱 실패하면 그냥 문자열로 넣는다.

배운 점

로그는 "한 줄에 하나의 이벤트"가 원칙이다. 여러 줄에 나눠 찍으면 동시 요청 환경에서 추적이 불가능하다
ContentCachingRequestWrapper를 쓰지 않으면 바디 로깅 시 스트림 소비 문제가 생긴다
요청 스코프 빈(SCOPE_REQUEST)으로 StopWatch를 관리하면 응답 시간 측정이 깔끔하다
헬스체크 로깅 제외는 배포 첫날에 바로 넣어야 한다. 로그가 노이즈로 가득 차면 정작 필요한 로그를 찾기 어렵다
trace_id를 로그에 포함시키면 "이 로그가 어떤 트레이스에 속하는지" 바로 연결할 수 있다