Logback + TraceId 기반 로깅 설정하기

개요

앞서 소개한 KotlinLogging 라이브러리를 통해 로깅 기능을 적용하면서 Logback을 사용하여 설정 했다.

이번에는 기본적인 Logback 설정 방법과 적용 과정에서 발생했던 이슈를 정리하려 한다.

KotlinLogging 라이브러리 사용기

---

Logback 설정

logback.xml 구성

다음은 내가 적용한 logback.xml 설정이다.

<configuration>
    <property name="LOG_PATH" value="logs/"/>
    <property name="LOG_FILE" value="${LOG_PATH}/application.log"/>

  	<!-- 콘솔 출력 -->
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss} %-5level [%X{traceId:-NO_TRACE}] %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

  	<!-- 파일 출력 -->
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_FILE}</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
          	<!-- 테스트를 위해 분 단위로 설정함 -->
            <fileNamePattern>${LOG_PATH}/application.%d{yyyy-MM-dd_HH-mm}.log</fileNamePattern>
            <maxHistory>7</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss} %-5level [%X{traceId:-NO_TRACE}] %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

  	<!-- 전체 로그 레벨 설정 -->
    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="FILE"/>
    </root>

  	<!-- 프로젝트 패키지 로깅 레벨 설정 -->
    <logger name="noul.oe" level="TRACE" additivity="false">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="FILE"/>
    </logger>
</configuration>

• appender : 로그를 출력할 대상읠 정의한다.
  • ConsoleAppender : 로그를 터미널 또는 IDE 콘솔에 출력한다.
  • RollingFileAppender : 일정 주기로 로그 파일을 분할 저장한다.
  • TimeBasedRollingPolicy : 지정된 주기로 파일이 롤링된다.
  • maxHistory : 지정한 개수만큼만 보관한다. (이후 삭제)

• %X{traceId:-NO_TRACE} : MDC에 TraceId가 없을 경우 NO_TRACE로 표기된다.
• root logger : 모든 로그의 기본 경로이다. 여기에 설정된 레벨 이하의 로그만 출력된다.
• logger name="noul.oe" : 지정한 패키지 이하의 로그만 출력된다.
• additivity="false" : root logger로 로그를 전파하지 않도록 한다.

전체 로그가 출력되는 이슈

위 xml의 root에는 INFO레벨 그리고 프로젝트 로그 레벨은 TRACE로 설정되어 있다.

하지만 위처럼 프로젝트 로그 레벨을 설정하지 않거나 root의 로그 레벨을 TRACE, DEBUG로 지정하는 경우에는 내가 원하지 않는 Spring 내부의 로그까지 모두 출력될 수 있다.

만약 아래와 같이 설정한다면 이런 로그들을 모두 만날 수 있다.

	<root level="TRACE">
		<appender-ref ref="CONSOLE"/>
		<appender-ref ref="FILE"/>
	</root>

	@Test
	fun loggingTest() {
		log.info { "첫 번째 로그입니다." }
		log.info { "두 번째 로그입니다." }
	}

위 이미지는 극히 일부의 로그만을 캡처한 것이다..

이러면 너무 많은 로그가 찍혀서 중요한 정보만 찾기 어려워지고, 로그 파일 크기도 급격히 커지는 문제가 발생한다.

불필요한 로그들까지 남기지 않으려면 아래와 같이 root에는 적절한 로그 레벨(나의 경우에는 INFO)을 지정하고 프로젝트 패키지에는 별도의 로그 레벨을 지정하면 된다.

    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="FILE"/>
    </root>

    <logger name="noul.oe" level="TRACE" additivity="false">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="FILE"/>
    </logger>

이렇게 설정하면 프로젝트 관련 로그만 세부 레벨로 남기고, 나머지 불필요한 로그는 제외할 수 잇다.

로그가 두 번씩 출력되는 문제

Logback은 기본적으로 하위 logger에서 발생한 로그 이벤트를 상위 logger로 전파한다.

나는 logger를 따로 설정했기 때문에 additivity="false"를 설정해주지 않으면, 로그가 상위 logger로 전파되어 그쪽 appender에서도 다시 출력하여 아래처럼 두 번씩 출력된다.

하위 logger에서 발생한 로그 이벤트를 상위로 전파하지 못하도록 additivity="false"를 설정하면 된다.

요청/응답 로깅 필터로 처리하기

나는 Api 요청의 시작/종료 시점을 로깅하고자 했고 필터에서 처리하는 것이 적절하다고 판단했다.

그래서 Spring이 제공하는 OncePerRequestFilter를 상속하여 로깅 필터를 구현했다.

이 필터는 하나의 요청에 대해 단 한 번만 실행되도록 보장해주기 때문에 중복 호출 없이 안정적으로 요청 전후 흐름을 추적할 수 있다.

private val filterLogger = KotlinLogging.logger {}

@Component
class LoggingFilter : OncePerRequestFilter() {
    private val excludedPaths = listOf("/css/", "/js/", "/images/", "/favicon.ico")

    init {
        println("LoggingFilter initialized")
    }

    override fun doFilterInternal(
        request: HttpServletRequest,
        response: HttpServletResponse,
        filterChain: FilterChain
    ) {
        try {
            val uri = request.requestURI
            if (excludedUri(uri) || excludedHtml(request)) { // 정적 리소스 로깅 제외
                filterChain.doFilter(request, response)
                return
            }

            val traceId = generateTraceId()
            MDC.put("traceId", traceId)

            val method = request.method
            val query = request.queryString?.let { "?$it" } ?: ""
            val fullUrl = "$uri$query"
            filterLogger.trace { "[$method] $fullUrl request called" }
            filterChain.doFilter(request, response)
            filterLogger.trace { "[$method] $fullUrl request finished" }

        } finally {
            MDC.clear()
        }
    }

    private fun generateTraceId(): String {
        return UUID.randomUUID().toString().substring(0, 8)
    }

    private fun excludedUri(uri: String): Boolean {
        return excludedPaths.any { uri.startsWith(it) }
    }

    private fun excludedHtml(request: HttpServletRequest): Boolean {
        val accept = request.getHeader("Accept") ?: ""
        return accept.contains("text/html")
    }
}

TraceId로 요청 단위 로그 추적하기

단일 스레드 환경에서는 로그 메시지에 스레드명만 있어도 추적이 가능하지만,
추후 멀티스레드 환경이나 병렬 요청 처리가 이루어질 경우 TraceId를 추가해주는 것이 로구 추적에 큰 도움이 된다.

TraceId는 요청마다 고유하게 생성되며, 다음과 같이 적용할 수 있다.

val traceId = UUID.randomUUID().toString().substring(0, 8)
MDC.put("traceId", traceId)

• MDC(Mapped Diagnostic Context)는 스레드 단위로 관리되는 저장 공간이다.
• 여기에 traceId를 넣어주면 로깅 패턴의 %X{traceId}로 간편하게 출력할 수 있다.
• 비동기 처리나 멀티스레드 환경에서는 MDC context를 명시적으로 전파하여 로그를 추적할 수 있다.

정적 리소스 요청 로그에서 제외하기

테스트를 하면서 보니까 나는 HTTP 요청/응답과 api 로직만 로깅해서 확인하고 싶은데, 화면을 호출하는 요청/응답 URI도 로그에 모두 찍히고 있었다.

그래서 Filter에서 경로를 검사해 해당 로직들은 로그에 찍히지 않도록 제외 처리했다.

val uri = request.requestURI
	if (excludedUri(uri) || excludedHtml(request)) { // 정적 리소스 로깅 제외
	filterChain.doFilter(request, response)
	return
}

---
private fun excludedUri(uri: String): Boolean {
	return excludedPaths.any { uri.startsWith(it) }
}

private fun excludedHtml(request: HttpServletRequest): Boolean {
	val accept = request.getHeader("Accept") ?: ""
	return accept.contains("text/html")
}

---

참고

Logback 공식 문서