Logback 로깅과 MDCFilter로 로깅 식별자 적용하기

로깅

로깅은 프로그램 동작 시 발생하는 모든 일(서비스 동작 상태 및 장애)을 기록하는 행위를 말한다. 이를 통해 개발, 테스트, 운영 등 다양한 환경에서 애플리케이션의 동작을 이해하고 모니터링하는 데 도움이 된다.

• 서비스 동작 상태: 시스템 로딩, HTTP 통신, 트랜잭션, DB 요청, 의도를 가진 Exception, ...
• 장애(exception, error): I/O Exception, NullPointerException, 의도하지 않은 Exception, ...

 

로깅은 언제할까?

정답이 없다. 프로젝트의 성격에 맞게 팀에 맞게 정의하면 된다. 그리고 로깅 시점은 때에 따라 다르다. 언제 기록할지를 정했다면 어떻게 기록할지도 중요한 부분이다. 우리가 아는 가장 로깅하기 쉬운 방법에는 System.out.println()과 System.err.println()이 있다. 하지만 이 가장 쉬운 방법을 사용하지 말라고 하는 것일까? 그에 대한 이유에 대해서 알아보자.

 

System.out.println()의 문제점

println() 메서드는 newLine() 메서드를 호출하고, newLine() 메서드를 살펴보면 synchronized 키워드가 있는 것을 확인할 수 있다. 이때 newLine() 메서드는 임계영역이 된다. 즉, 멀티스레딩 환경에서 A 스레드가 newLine() 메서드를 실행하면 해당 메서드는 잠기게 되어 다른 스레드가 들어올 수 없다.

이렇게 System.out.println() 메서드를 사용했을때 큰 성능 이슈가 발생할 수 있고, 그 외 로그 레벨을 지정할 수 없는 등의 문제가 있기 때문에 로깅 프레임워크를 사용하는 것을 권장한다. 

 

로깅 프레임워크(Logging Framework)

SLF4J, Logback과 같은 로깅 프레임워크가 있다. 로깅 프레임워크는 출력 형식을 지정할 수 있고, 로그 레벨에 따라 남기고 싶은 로그를 별도로 지정할 수 있다. 그리고 콘솔 뿐만 아니라 파일이나, 네트워크 등 로그를 별도에 위치에 남길 수 있다. 그리고 성능도 로깅 프레임워크가 좋고 위에서 봤듯이 System.out.println()으로 사용하는 것에는 치명적인 부분이 있다. 따라서 실제 서비스에서는 로깅 프레임워크를 사용하는 것이 좋다.

 

로그 레벨

레벨	설명
Fatal	매우 심각한 에러. 프로그램이 종료되는 경우가 많음.
Error	의도하지 않은 에러가 발생한 경우. 프로그램이 종료되진 않음.
Warn	에러가 될 수 있는 잠재적 가능성이 있는 경우
Info	명확한 의도가 있는 에러, 요구사항에 따라 시스템 동작을 보여줄 때
Debug	Info 레벨보다 더 자세한 정보가 필요한 경우. Dev 환경
Trace	Debug 레벨보다 더 자세함. Dev 환경에서 버그를 해결하기 위해 사용

위는 로깅에서 가장 중요한 어떻게 로그를 남길까에 대한 고민은 로그 레벨을 통해 해결할 수 있다. 각 레벨에 따라 발생하는 상황에 따라 로깅을 남길 수 있는데 회원가입 시, DB에 동일한 email을 가진 회원이 있을 때 EmailDuplicationException을 던진다면 이 이벤트의 로그는 어떤 레벨을 적용할까? 개발자가 의도한 에러이기 때문에 정답은 Info이다! 시스템 상에서 개발자가 의도하지 않은 예외를 나타날 때는 Error 레벨 이상을 사용하고 의도한 예외를 나타낼 때는 그 아래쪽으로 기준으로 두면 된다.

 

로깅 vs 디버깅

예외 상황을 가장 잘 파악할 수 있는 것이 디버깅이다. 즉, 프로그래밍의 절반은 디버깅이지만 실제 서버가 구동되는 중이라면 디버깅을 하기에는 무리가 있다. 따라서 디버깅을 쓸 수 있다면 디버깅을 최대한 활용하고, 디버깅을 할 수 없는 상황에서는 로깅이 최선의 선택이라고 볼 수 있다.

 

SLF4J

Simle Logging Facade for Java의 약자로 다양한 로깅 프레임워크에 대한 추상화(인터페이스) 역할을 하는 프레임워크이다. SLF4J는 추상 로깅 프레임워크이기 때문에 단독으로 사용하지 않고 최종 사용자가 배포 시 원하는 로깅 프레임워크를 결정하고 사용해도 SLF4J가 인터페이스화 되어있기 때문에 SLF4J를 의존하는 클라이언트 코드에서는 실제 구현은 몰라도 된다. 개방 폐쇄 원칙, 의존관계 역전 법칙이 잘 사용되었다고 볼 수 있다.

 

SLF4J의 동작과정을 간략히 설명하면 개발할 때는 SLF4J API를 사용하여 로깅 코드를 작성하고 배포할 때는 바인딩된 Logging Framework가 실제 로깅 코드를 수행하는 과정을 거친다. 이러한 과정은 SLF4J에서 제공하는 3가지 모듈인 Bridge, API, Binding 모듈을 통해 수행될 수 있다. 구현 프레임워크를 Logback으로 정했다.

• Bridge 모듈은 SLF4J 이외의 다른 로깅 API로의 Logger 호출을 SLF4J 인터페이스로 연결하여 SLF4J API가 대신 처리할 수 있도록 하는 일종의 어댑터 역할을 하는 라이브러리이다. 아직 변경되지 않은 이전의 레거시 로깅 프레임워크를 위한 라이브러리이다. 여러 개를 사용해도 상관없지만 Bridge와 Binding 모듈에 같은 종류의 프레임워크를 사용하면 안된다.
• SLF4J API 모듈은 로깅에 대한 추상 레이어(인터페이스)를 제공한다. 결론적으로 로깅 동작에 대한 역할을 수행할 추상 메서드를 제공한다고 보면 된다. 주의해야할 점은 하나에 API에 하나의 Binding을 두어야 한다.
• Binding 모듈은 SLF4J API를 로깅 구현체(Logging Framework)와 연결하는 연결하는 어댑터 역할을 하는 모듈이다. SLF4J API를 구현한 클래스에서 Binding으로 연결될 Logger의 API를 호출한다. 앞서 API의 주의점과 같이 하나에 API에 하나의 Binding을 두어야 한다.

 

Logback 구조

Logback은 로깅 프레임워크 중 하나로 SLF4J의 구현체이다. Log4j를 토대로 만든 프레임워크고, 현재 logback을 많이 사용한다. 스프링 프레임워크에서도 SLF4J와 Logback을 채택하고 있다.

 

Logback은 위 그림처럼 3가지 모듈로 나뉜다.

• logback-core: 다른 두 모듈을 위한 기반 역할을 하는 모듈이다. Appender와 Layout 인터페이스가 이 모듈에 속한다.
• logback-classic: logback-core에서 확장된 모듈로 logback-core를 가지며 SLF4J API를 구현한다. Logger 클래스가 이에 속한다.
• logback-access: Servlet Container와 통합되어 HTTP 액세스에 대한 로깅 기능을 제공한다. logback-core는 logback-access의 기반기술이기에 필요하지만 logback-classic 및 slf4j와 무관하다. 웹 어플리케이션 레벨이 아닌 컨테이너 레벨에서 설치되어야 한다.

 

Logback 설정요소

Logback을 이용해 로깅을 수행하기 위해서 필요한 주요 설정요소로는 Logger, Appender, Layout(Encoder) 3가지가 있다.

 

Logger

실제 로깅을 수행하는 구성요소이다. 로거가 사용 가능한 다섯 가지 레벨인 TRACE, DEBUG, INFO, WARN, ERROR 속성을 통해서 출력할 로그의 레벨을 조정할 수 있다. 기본 로그의 레벨은 아래와 같으며, 지정된 레벨 이하의 메서드는 기록도지 않고, 기본 레벨은 DEBUG이다.

TRACE < DEBUG < INFO < WARN < ERROR

 

Appender

Logback은 로그 이벤트를 write하는 작업을 Appender에게 위임한다.  즉, Appender는 로그 메세지가 출력될 대상을 결정한다. Appender의 구현 클래스 중 OutputStreamAppender의 하위 클래스는 다음과 같다.

• UnsynchronizedAppenderBase: synchronized한 동작이 필요하지 않을 때 사용한다.
• OutputStreamAppender: java.io.OutputStream에 로그 이벤트를 append한다. 추상 클래스이기 때문에 이를 직업 사용하지 않고 하위 클래스에 책임을 위임한다.
• ConsoleAppender: 콘솔에 System.out 또는 System.err를 이용하여 로그 이벤트를 appendgksek.
• FileAppender: 파일에 로그 이벤트를 append한다.
• RollingFileAppender: FileAppender를 상속하여 로그 파일을 rollover(타켓 파일을 바꾸는 것)한다. log.txt를 타겟파일로 로그 메시지를 append하다 어느 조건(시간, 크기)에 다다르면, 이전 파일을 저장하고, 타켓 파일을 바꾼다.

 

Encoder(Layout)

Encoder는 로그 이벤트를 바이트 배열로 변환하고, 해당 바이트 배열을 OutputStream에 쓰는 작업을 담당한다. 즉, Appender에 포함되어 사용자가 지정한 형식으로 표현 될 로그 메시지를 변환하는 역할을 담당하는 요소이다.

 

Logging 적용하기

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
    <springProfile name="!prod">
        <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
            <encoder>
                <pattern>[%d{yyyy-MM-dd HH:mm:ss}:%-4relative] %green([%thread]) %highlight(%-5level)
                    %boldWhite([%C.%M:%yellow(%L)]) - %msg%n
                </pattern>
            </encoder>
        </appender>

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

resources 폴더에 logback-spring.xml 파일을 만들고 아래와 같이 설정해준다.

• [%d{yyyy-MM-dd HH:mm:ss}:%-4relative]
  • %d{yyyy-MM-dd HH:mm:ss}: 이벤트가 발생한 날짜와 시간을 형식에 맞춰 출력한다. 여기서는 "년-월-일 시:분:초"형식이다.
  • :%-4relative: 상대적인 시간을 나타낸다. 이벤트가 발생한 시점부터 현재까지의 시간을 밀리초로 나타낸다. %-4는 필드의 폭을 나타내고 -는 왼쪽 정렬을 의미한다.
• %green([%thread])
  
  • %thread: 로그 이벤트를 처리하는 스레드의 이름을 출력한다.
• %boldWhite([%C.%M:%yello(%L)])
  • [%C.%M:%yello(%L)]: 이벤트가 발생한 클래스와 메서드, 그리고 라인 번호를 출력한다. %C는 클래스 이름, %M는 메서드 이름, %L는 라인 번호를 나타낸다.
• %msg%n
  • %msg: 로그 메시지를 출력한다.
  • %n: 새로운 라인 문자를 추가하여 다음 로그 이벤트가 새로운 줄에서 시작하도록 한다.

위 패턴을 종합하면, 각 로그 이벤트는 다음과 같은 형식으로 출력될 것이다.

[날짜 및 시간:상대적 시간] (스레드 이름) 로그레벨 (클래스명.메서드:라인번호) - 로그 메시지

 

로그 출력 확인하기

만약 이미 회원가입한 이메일이 있다면 EmailDuplicationException 예외가 발생하면서 로깅이 출력되는 로직을 작성했다. 만약 이미 가입한 이메일로 요청을 보내게 되면 위처럼 결과가 출력되는 것을 확인할 수 있다.

 

MDCFilter 적용

ThreadLocal을 사용하여 로깅하기 + MDCFilter

MDCFilter는 멀티스레딩 환경에서 스레드 간에 데이터를 공유하지 않고 각 스레드마다 독립적으로 데이터를 보관하고 접근할 수 있게 해주는 ThreadLocal 클래스를 활용하여 로그마다 식별자가 찍히도록 해주는 필터의 한 유형을 말한다. 이는 멀티 스레딩 환경에 여러 요청이 처리되기 때문에 동일한 요청에 대한 로그가 연속적으로 쌓이는 것이 아니라 순서없이 쌓이기 때문에 어떤 스레드에 대한 로그인지 파악하기 힘들기 때문에 사용하는데 자세한 내용은 위 블로그를 참고하자.

 

MDCFilter 적용

@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
public class MDCLoggingFilter extends OncePerRequestFilter {

    private static String REQUEST_ID = "request_id";

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response,
       FilterChain filterChain) throws ServletException, IOException {

       UUID uuid = UUID.randomUUID();
       MDC.put(REQUEST_ID, uuid.toString());
       filterChain.doFilter(request, response);
       MDC.clear();
    }
}

OncePerRequestFilter는 Spring에서 제공하는 필터 중 하나로, 각 HTTP 요청당 한 번만 실행되도록 보장하는 역할을 한다. 그리고 해당 필터는 MDC(Mapped Diagnostic Context)를 사용하여 HTTP 요청에 대한 고유한 요청 ID를 생성하고 로그에 포함시키는 역할을 한다.

 

logback-spring.xml

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
    <springProfile name="!prod">
        <property name="LOG_PATTERN"
                  value="[%X{request_id:-startup}] %d{yyyy-MM-dd HH:mm:ss}:%-4relative %green([%thread]) %highlight(%-5level) %boldWhite([%C.%M:%yellow(%L)]) - %msg%n"/>
        <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
            <encoder>
                <pattern>${LOG_PATTERN}</pattern>
            </encoder>
        </appender>

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

logback-spring.xml을 다시 로그 패턴으로 수정해줘야 한다.

• %X{request_id:-startup}: MDC에서 request_id라는 키에 대한 값을 로깅한다. MDC는 로그 메시지에 추가 정보를 동적으로 추가할 수 있게 하는 메커니즘이다. -startup은 만약 request_id가 MDC에 없다면 기본값으로 startup을 사용하라는 의미이다.

 

MDCFilter 적용 결과 확인하기

위 로깅에 대해 출력된 결과를 보면 왼쪽에 요청 ID를 같이 출력하도록 만들어 여러 스레드가 쌓여도 추적하는데 편리성을 줄 수 있다.

 

prod 환경 시 로깅(file-info-appender.xml)

<included>
    <appender name="FILE-INFO" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>./log/info/info-${BY_DATE}.log</file>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>INFO</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <encoder>
            <pattern>${LOG_PATTERN}</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>./backup/info/info-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>100MB</maxFileSize>
            <maxHistory>30</maxHistory>
            <totalSizeCap>3GB</totalSizeCap>
        </rollingPolicy>
    </appender>
</included>

이 Logback 설정은 파일로 로그를 기록하는 RollingFileAppender를 정의하고 다음과 같은 특징을 가진다.

• 로그 파일 경로 설정: <file>./log/info/info-${BY_DATE}.log</file>를 통해 로그 파일의 경로와 파일 이름을 지정한다.
• 로그 레벨 필터
  • <fillter class="ch.qos.logback.classic.filter.LevelFilter">: appender에 적용되는 레벨 필터를 설정한다.
  • <level>INFO</level>: INFO 레벨 이상의 로그만을 해당 appender에 기록한다.
  • <onMatch>ACCEPT</onMatch>: 지정된 레벨에 대해서 허용한다.
  • <onMismatch>DENY</onMismatch>: 지정된 레벨 이외의 다른 레벨에 대해서 거부한다.
• 롤링 파일 설정
  • <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">: 크기와 시간 기반으로 파일 롤링 정책을 설정한다.
  • <fileNamePattern>./backup/info/info-%d{yyyy-MM-dd}.%i.log</fileNamePattern>: 롤링된 파일의 이름 패턴을 지정한다. %d{yyyy-MM-dd}는 날짜를 나타내며 %i는 인덱스이다.
  • <maxFileSize>100MB</maxFileSize>: 각 로그 파일의 최대 크기를 지정한다. 100MB로 설정되어 있으므로 100MB를 초과하면 새로운 파일이 생성된다.
  • <maxHistory>30</maxHistory>: 보존할 로그 파일의 최대 기록 수이다. 30으로 설정되어 있으므로 최근 30일치의 로그 파일이 유지된다.
  • <totalSizeCap>3GB</totalSizeCap>: 모든 로그 파이르이 총 크기 상한을 지정한다. 3GB로 설정되어 있으므로 이 크기를 초과하면 가장 오래된 파일부터 삭제된다.

 

로깅 파일 출력

이전에 봤던 로그들이 파일에 기록되는 것을 확인할 수 있다.

 

 

출처

[10분 테크톡] 검프의 Logging(로깅) #1

[10분 테크톡] 검프의 Logging(로깅) #2

[Logging] Logback이란?