Logback, Logback-access로 로깅하기(+ MDC로 클라이언트 요청 고유 아이디 생성)

hongo·2024년 4월 24일
1

Logback의 로그 레벨 5단계

프로젝트마다 어떤 상황에서 어떤 로그 레벨을 쓸지는 자유지만 보통 아래와 같다고 한다!

  • Error : 예외처리하지 못한, 예상치 못한 에러가 발생했을 때
  • Warn : 예상한 예외 상황, 당장 문제가 생기진 않았지만 문제가 우려되는 경우(커넥션이 평소의 3배 증가했다던가!)
  • Info : 중요한 비즈니스 프로세스 처리 결과
  • Debug : 개발 단계에서 주로 사용함. SQL 로깅에 자주 사용
  • Trace : 개발 단계에서 주로 사용함22. 특정 로직을 상세하게 추적하고 싶을 때!

프로젝트에서는 5개의 레벨을 모두 사용할 필요성을 느끼지 못해서 Error, Warn , Info 세 가지만 사용하기로 했다! 애초에 Debug 랑 Trace 는 운영 단계에서 사용할 경우가 없기도 하고…ㅎ.ㅎ

logback-spring.xml로 로깅 설정

logback-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true">
    <springProfile name="prod"> <!-- 로그가 적용되는 프로필 설정 가능 -->
        <include resource="org/springframework/boot/logging/logback/defaults.xml"/> <!-- logback의 기능을 전부 사용하기 위해 include 필요. include안하면 몇몇 layout 적용 안됨 -->

        <timestamp key="DATE" datePattern="yyyy-MM-dd"/> <!-- 자주 사용되는 DATE 포맷을 변수로 설정 가능 -->
        <timestamp key="DATE_SEC" datePattern="yyyy-MM-dd HH:mm:ss"/>

        <include resource="console-appender.xml"/> <!-- 이후 생성할 xml파일을 가져옴 -->
        <include resource="info-appender.xml"/>
        <include resource="warn-appender.xml"/>
        <include resource="error-appender.xml"/>

        <root level="info"> <!-- Appender가 적용되는 로그 레벨 설정 가능 (예시의 경우 info이상인 레벨에 적용된다!) -->
            <appender-ref ref="CONSOLE"/> <!-- Appender 등록 ~-.appender.xml에서 생성한 어펜더를 등록 -->
            <appender-ref ref="FILE-INFO"/>
            <appender-ref ref="FILE-ERROR"/>
            <appender-ref ref="FILE-WARN"/>
        </root>
    </springProfile>
</configuration>

appender.xml 예시

console-appender.xml

<included> <!-- 다른 파일에서 include시 포함되는 내용 -->
    <conversionRule conversionWord="clr" converterClass="org.springframework.boot.logging.logback.ColorConverter"/> <!-- 로그 색을 설정할 수 있는 컨버터 -->

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"> <!-- 콘솔 출력 Appender를 생성-->
        <encoder>
            <pattern> <!-- 로깅 포맷 설정 -->
${DATE_SEC} [%thread] %clr(%5level) %cyan(%logger) - %msg
%ex
            </pattern>
            <charset>utf8</charset>
        </encoder>
    </appender>
</included>

${} 로 변수 참조 가능(ex. ${DATE_SEC})

% 로 logback이 제공하는 layout 표현 사용 가능
ex)

  • %clr : 특정 로그 메시지나 레벨에 색을 칠함 ex) %clr(%5level) : 로그 5레벨을 디폴트 색으로 표기, %clr(%thread){cyan} : 스레드 이름을 시안색으로 표기
  • %cyan : 시안색으로 표기. %clr 없이 바로 특정 로그 패턴에 색을 칠할 수 있음. (챗지피티왈, 버전에 따라 호환이 되지 않을 수 있으니 %clr이 명확하다는 데 확인 필요)
  • %thread : 로그를 출력하는 스레드 이름을 가져옴
  • %msg : response message를 가져옴
  • %ex : 예외 발생시, 스택 트레이스를 가져옴

자세한 내용 참고 : https://logback.qos.ch/manual/layouts.html

  • 출력 예시

error-appender.xml

<included>
    <appender name="FILE-ERROR" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>ERROR</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>

        <file>../logs/error/${DATE}.log</file>
        <encoder>
            <pattern>
[requestId: %X{requestId:-NO REQUEST ID}]
timestamp: ${DATE_SEC},
message: %message,
exception: %ex
%n
            </pattern>
            <charset>utf8</charset>
        </encoder>

        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>../logs/backup/error/%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>50MB</maxFileSize>
            <maxHistory>7</maxHistory>
            <totalSizeCap>1GB</totalSizeCap>
        </rollingPolicy>
    </appender>
</included>
  • 출력 예시
[requestId: 1812d295-f30c-4887-8e86-3cd8cba85a62]
timestamp: 2024-02-13 03:36:27,
message: 예상하지 못한 예외가 발생했습니다. URI: /favicon.ico, No static resource favicon.ico.,
exception: org.springframework.web.servlet.resource.NoResourceFoundException: No static resource favicon.ico.
	at org.springframework.web.servlet.resource.ResourceHttpRequestHandler.handleRequest(ResourceHttpRequestHandler.java:585)
	(편의상 줄임)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.base/java.lang.Thread.run(Thread.java:833)

logback-access

logback-spring은 로그 레벨 별로 발생한 스택 트레이스, 응답 메시지 등을 출력하기에는 편리하지만, 클라이언트 요청 정보를 출력하기에는 부족하다.
logback-access를 사용하면 클라이언트의 요청을 로깅할 수 있다. logback-access를 사용해보자!

우선 gradle에서 logback-access 설정을 추가한다.implementation("ch.qos.logback:logback-access")

application.yml에서 logback-access설정을 간편하게 할 수 있지만, xml파일에서 더 커스텀하고 싶다면 아래와 같이 LogbackValve설정을 해주어야한다. logback-access 설정을 할 xml파일 이름을 지정해주자.

logback-access.xml에서 사용되는 레이아웃 표현이랑, application.yml에서 사용되는 표현과 차이가 있는데 xml을 사용했을 때 더 많은 기능을 사용할 수 있다. 나는 %fullRequest와 줄 띄움을 사용하고 싶어서 xml로 설정했다.


@Configuration
class AccessLogConfig {

    @Bean
    fun webServerFactoryCustomizer(): WebServerFactoryCustomizer<TomcatServletWebServerFactory> {
        return WebServerFactoryCustomizer<TomcatServletWebServerFactory> { factory ->
            val logbackValve = LogbackValve()
            logbackValve.filename = "logback-access.xml"
            factory.addContextValves(logbackValve)
        }
    }
}

모든 요청을 로깅하는 것은 낭비인 것 같아서, 에러가 발생했을 경우에만 로깅을 하게 했다. (event.getStatusCode() >= 400)

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true">
    <springProfile name="prod">
        <include resource="org/springframework/boot/logging/logback/defaults.xml"/>

        <timestamp key="DATE" datePattern="yyyy-MM-dd"/>
        <timestamp key="DATE_SEC" datePattern="yyyy-MM-dd HH:mm:ss"/>

        <appender name="FILE-ACCESS" class="ch.qos.logback.core.rolling.RollingFileAppender">
            <filter class="ch.qos.logback.core.filter.EvaluatorFilter">
                <evaluator>
                    <expression>event.getStatusCode() >= 400</expression>
                </evaluator>
                <onMismatch>DENY</onMismatch>
            </filter>

            <file>../logs/access/${DATE}.log</file>
            <encoder>
                <pattern>
[requestId: %reqAttribute{requestId}]
timestamp: ${DATE_SEC},
%fullRequest
%n
                </pattern>
                <charset>utf8</charset>
            </encoder>

            <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
                <fileNamePattern>../logs/backup/access/%d{yyyy-MM-dd}.%i.log</fileNamePattern>
                <maxFileSize>50MB</maxFileSize>
                <maxHistory>7</maxHistory>
                <totalSizeCap>1GB</totalSizeCap>
            </rollingPolicy>
        </appender>

        <appender-ref ref="FILE-ACCESS" />
    </springProfile>
</configuration>
  • 출력 예시
[requestId: 1930dbf2-e3c0-4171-ab13-7b21671e065d]
timestamp: 2024-02-13 04:56:47,
DELETE /carts/1 HTTP/1.1
content-type: application/json
authorization: Bearer eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJtZW1iZXJJZCI6IjIiLCJhdXRob3JpdHkiOiJNRU1CRVIiLCJpYXQiOjE3MDc3Njc4MjAsImV4cCI6MTcwNzc3MTQyMH0._ZZPlet59ljlnoZ7DBP5Rec2BDM4gqcNTBNGCwUZJ_w
accept: */*
host: localhost:52584
connection: Keep-Alive
user-agent: Apache-HttpClient/4.5.13 (Java/18.0.2)
accept-encoding: gzip,deflate
cookie: refresh-token=eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJtZW1iZXJJZCI6IjIiLCJhdXRob3JpdHkiOiJNRU1CRVIiLCJpYXQiOjE3MDc3Njc4MjAsImV4cCI6MTcwNzc3MTQyMH0._ZZPlet59ljlnoZ7DBP5Rec2BDM4gqcNTBNGCwUZJ_w

MDC(Mapped Diagnostic Context)

MDC는 로깅 프레임워크에서 지원하는 기능으로, 스레드마다 Map형태의 자료구조를 제공한다. 내부적으로 ThreadLocal을 사용하고 있으며 각 스레드마다 클라이언트 ID, 세션 ID등 정보를 Map에 저장하여 로깅에 사용한다.

클라이언트의 요청. API요청별로 고유한 아이디를 생성해서 로그에 포함시킨다면, API별로 로그를 보기 편리할 것이다.

MDC를 사용해서 클라이언트 요청마다 고유한 아이디를 생성해서 저장해보자.
클라이언트 요청이 들어오는 시점에 요청을 가로채서 고유한 아이디를 만들어주면 될 것 같다! Filter를 사용해 들어오는 모든 요청들에 대해 아이디를 생성해주었다.

import org.slf4j.MDC
import org.springframework.stereotype.Component

private const val REQUEST_ID = "requestId" // Map 형태이므로 key를 설정해줘야한다. 이 key는 이후 로그 포맷에서 데이터를 가져올 때 사용한다.

@Component
class MdcFilter : Filter {

    override fun doFilter(request: ServletRequest, response: ServletResponse, chain: FilterChain) {
        val requestId = UUID.randomUUID().toString()
        MDC.put(REQUEST_ID, requestId)
        chain.doFilter(request, response)
        MDC.clear();
    }
}

비동기 작업을 수행하는 메서드의 경우, 기존 스레드가 아닌 별도의 스레드로 수행되기 때문에 위에서 생성한 MDC(TheadLocal사용)에 접근할 수 없다.

하지만 TaskDecorator를 사용하면 비동기 스레드를 실행하기 전 작업을 추가할 수 있다. TaskDecorator를 사용해서 비동기 스레드를 실행하기 전에 MDC를 복사해주자!

import org.slf4j.MDC
import org.springframework.core.task.TaskDecorator

class MdcTaskDecorator : TaskDecorator {

    override fun decorate(runnable: Runnable): Runnable {
        val copyOfContextMap = MDC.getCopyOfContextMap()
        return Runnable {
            MDC.setContextMap(copyOfContextMap)
            runnable.run()
        }
    }
}

생성한 Decorator를 비동기 스레드 풀에 설정해주면 된다!

@Configuration
@EnableAsync
class AsyncConfig {

    @Bean
    fun taskExecutor(): TaskExecutor {
        val taskExecutor = ThreadPoolTaskExecutor()
        taskExecutor.setTaskDecorator(MdcTaskDecorator)
        return taskExecutor
    }
}

참고

profile
hongo
이전 포스트

주문 상태 동시성 이슈 해결

다음 포스트

파일 시스템 내부구조

2개의 댓글

comment-user-thumbnail
jeyong
2024년 7월 30일

"%clr : 시안색 적용" 오타인 것 같아요!

1개의 답글