Log4j2 AsyncLogger와 함께 하는 Logging 환경 구축

공병주(Chris)·2023년 2월 14일
Log4J2logging졸업작품 Dandi
2
post-thumbnail

2023 글로벌미디어학부 졸업 작품 프로젝트 Dandi 에서 Logging 환경을 구축했던 과정을 기록하려 합니다.

Logging

로깅은 운영, 개발 단계에서 개발자가 여러 환경, 상황에서 필요로 하는 정보를 기록하고 확인하기 위해서 필수적입니다. System.out.println을 통해서 기록할 수 있지만 환경마다 동일한 기준으로 기록해야한다는 한계가 존재합니다.

따라서, Logging이라는 개념이 등장했습니다. local, develop, deploy 등 여러 환경에 따라 어떤 데이터들을 기록할지 레벨로 나눠서 관리할 수 있습니다. 또한, System.out.println에 비해 Logging은 콘솔, 파일, 원격 서버 등 여러 곳에 기록을 할 수 있다는 장점도 있습니다.

Slf4j(Simple Logging Facade for java)

Slf4j는 Spring Boot에서 채택한 로깅 추상화 라이브러리입니다. 과거 java 진영에서 여러 로깅 프레임워크들이 호환 되지 않고 서로 경쟁하는 시대가 있었는데, Slf4j로 정리가 되었습니다.

이 역사는 제 팀원이었던 이스트의 테코톡에서 간단하게 다루니, 관심 있는 분들은 보셔도 좋을 것 같습니다.
https://www.youtube.com/watch?v=1IMJCg68-lU

Slf4j는 추상화 라이브러리입니다. 따라서, 개발자가 구현체를 설정하고 등록해줘야지 사용 가능합니다.

구현체(Log4j vs Logback vs Log4j2)

Slf4j의 구현체인 Log4j, Logback, Log4j2가 순서대로 등장했습니다. 차이를 살펴보고 어떤 구현체를 사용할지 정해보겠습니다.

Log4j와 Logback

Log4j의 개발자가 성능 향상과 SLF4J를 더 잘 support하기 위해서 등장했습니다.

가장 큰 차이는 자동 리로드라고 생각합니다. 로깅 설정이 변경되었을 때, Log4j는 서버를 재시작해야합니다. 하지만, Logback은 자동 리로드를 지원해서 서버를 재시작할 필요 없이 로깅 설정을 변경할 수 있습니다. 또한, Logback은 Log4j에 비해 다양한 필터링 옵션을 가져갈 수 있고 더 좋은 성능을 가지고 있습니다.

Logback과 Log4j2

Log4j2는 Log4j와 Logback를 보완하기 위해서 등장했습니다. Log4j2는 Logback처럼 필터링 옵션과 자동 리로드를 지원합니다. 가장 큰 차이는 의존성과 성능이라고 생각합니다.

Logback은 Slf4j과 함께 include되고 SpringBoot에 Slf4j에 대한 의존이 있어서 별다른 의존성을 주입할 필요가 없습니다. 반면에 Log4j2(Log4j도)는 의존성을 주입해줘야 합니다.

Log4j2는 멀티 스레드환경에서 비동기 로거가 Logback보다 많은 양을 처리할 수 있고, 대기 시간도 짧다고 합니다. 또한, 람다를 통한 Log Statement에 대한 Lazy Evaluation도 지원합니다.

또한, Garbage Free라는 개념으로 GC를 최소화합니다. Garbage Free는 아래에서 더 살펴보겠습니다.

성능에 대한 자세한 내용은 apache 공식 홈페이지에 나와있으니 참고하시면 될 것 같습니다.

https://logging.apache.org/log4j/2.x/performance.html

그렇다면 성능에 포커스를 두지 않고 가볍게 Logback을 사용하느냐, 의존성을 추가하고 성능 좋은 Log4j2를 사용하느냐의 문제로 보입니다.

Logback을 가볍게 사용할 수 있지만, 성능적으로 한두개도 아닌 여러 이점을 Log4j2가 가지기 때문에 Log4j2를 선택했습니다. 또한, 과거에 Log4j의 보안이슈가 있었는데, 특정 버전 이상에서는 문제 되지 않는다고 합니다.

로깅 전략

실제로 구축하기에 앞서, 환경에 따른 로깅 전략을 정해보겠습니다.

현재 prod 환경이 존재하지않지만 prod, dev, local 이 3가지 환경에서 로깅 전략을 살펴보겠습니다.

Appender 전략

Local 환경에선 로그파일을 저장할 필요 없이 Console로 로그를 보는 것이 충분하다고 생각해서 ConsoleAppender로 로그를 출력하기로 했습니다.

Dev 환경은 계속 서버가 가동시켜둘 것이기에, Console에 있는 로그들을 Trace 하는 것보다 File에 저장하는 것이 좋다고 판단해서 RollingFileAppender로 결정했습니다. 다만, 로그를 보관하는 기간을 7일로 Prod 환경보다 짧게 가져가려 합니다.

Prod 환경은 운영시 중요한 내용들을 File로 관리해야하기 때문에 RollingFileAppender를 택했습니다. 운영 로그들을 모니터링하고 로그를 기반으로 개선해야 할 부분이 있다고 생각되어 파일 보관기간은 30일로 정했습니다.

Logging Level 전략

Local과 Dev는 시스템을 개발하는 과정이기 때문에 많은 정보가 있으면 도움이 될 것이라고 생각합니다. 하지만, TRACE는 과할 것 같아 DEBUG로 결정했습니다. 단, Application이 실행될 때 모든 DEBUG 레벨의 로그들을 출력하면 실행 과정에서의 너무 많고 불필요한 정보들이 출력됩니다. 따라서, Root는 Info로 설정하고 제가 구성하는 패키지 하위에서만 DEBUG 레벨로 출력하도록 설정하려 합니다.

Prod 환경에서도 많은 정보가 있으면 좋지만, Logging 도 비용이기 때문에 운영시 중요한 정보들을 INFO 레벨로 로깅하기로 결정했습니다.

Slf4j와 Log4j2 dependency

이제 실제로 로깅 환경을 구축을 해보겠습니다. 아직 Prod 환경은 존재하지 않기 때문에 Local과 Dev 환경만 구축하겠습니다.

Log4j2 의존성 추가


dependencies {
    implementation 'org.springframework.boot:spring-boot-starter-log4j2'
    implementation 'com.fasterxml.jackson.dataformat:jackson-dataformat-yaml'
}

log4j2의 의존성을 추가해줍니다.

그리고, 보통 로깅은 xml으로 설정을 많이 하는데, 저는 xml 형식이 읽기 힘들어서 yml 형식 설정을 위해 com.fasterxml.jackson.dataformat:jackson-dataformat-yaml 의존성도 추가해주었습니다.

Logback 의존성 제거

Log4j2와 Slf4j의 내장 구현체 Logback과 충돌이 발생하면서 아래와 같은 오류가 발생합니다.

Class path contains multiple SLF4J bindings , log4j-slf4j-impl cannot be present with log4j-to-slf4j

따라서, Logback 의존을 제거해줍니다.

configurations { 
    all {
        exclude group: 'org.springframework.boot', module: 'spring-boot-starter-logging'
    }
}

Appender와 Logger

https://logging.apache.org/log4j/2.x/manual/configuration.html

로깅을 설정하는 방법은 apache 공식문서에 여럿 나와있습니다.

찾아보니 Appender 설정도 하고 Logger 설정도 해서 의아했는데요. 둘의 차이에 대해 알아보았습니다.

Appender
Appenders are responsible for delivering LogEvents to their destination. Appenders usually are only responsible for writing the event data to the target destination. In most cases they delegate responsibility for formatting the event to a layout

Appender는 로그이벤트를 파일, 콘솔 등의 최종 목적지로 전달하는 역할을 합니다. 또한, 대부분은 로그이벤트를 layout에 맞게 출력하는 역할도 합니다.

Logger
Loggers are responsible for capturing events (called LogRecords) and passing them to the appropriate Appender.

Logger는 로그이벤트를 감지하고 이를 Appender로 전달하는 역할을 합니다.

Log4j2 yml로 설정하기

local 환경

Configuration:
  name: Local-Logger
  status: debug

  appenders:
    Console:
      name: Console_Appender
      target: SYSTEM_OUT
      PatternLayout:
        pattern: "%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{35} - %msg%n"

	Loggers:
    Root:
      level: info
      AppenderRef:
        ref: Console_Appender
    Logger:
      name: dandi.dandi
      additivity: false
      level: debug
      AppenderRef:
        ref: Console_Appender

Appenders.Console

Local 환경은 Console에 출력할 것이라서 ConsoleAppender를 등록해주었습니다.

target

출력 방식입니다. SYSTEM_OUT 방식으로 출력하도록 지정했습니다.

Loggers.Root와 Loggers.Logger

Root는 info 레벨로 설정하고 dandi.dandi 패키지 하위는 debug 레벨로 설정했습니다. 이와 같이 하면 Servlet이나 ApplicationContext 등에서 발생하는 복잡한 일들은 로깅 되지 않습니다.

additivity

현재 Logger가 2개입니다. Root 로거와 dandi.dandi 로거입니다. 위와 같은 상황에선 동일한 로그 이벤트를 Root와 dandi.dandi가 handle해서 Appender에게 전달하기 때문에 동일한 로그가 두번 발생하는데요. 아래 공식문서의 글을 첨부해두었습니다. com.foo.Bar를 dandi.dandi로 대체해서 이해하시면 됩니다.

This is because the appender associated with logger com.foo.Bar
is first used, which writes the first instance to the Console. Next, the parent of com.foo.Bar
, which in this case is the root logger, is referenced. The event is then passed to its appender, which is also writes to the Console, resulting in the second instance. This is known as additivity. While additivity can be quite a convenient feature (as in the first previous example where no appender reference needed to be configured), in many cases this behavior is considered undesirable and so it is possible to disable it by setting the additivity attribute on the logger to false:

동일한 로그가 두번 발생하는 것은 보통 undesirable 한 것으로 여겨지기 때문에 false로 두어서 중복을 없애시면 됩니다.

dev 환경

dev는 RollingFileAppender로 설정했는데요.

https://logging.apache.org/log4j/2.x/manual/appenders.html#RollingFileAppender 문서를 참고하면서 설정했습니다.

Configuration:
  name: Dev-Logger
  status: debug

  Properties:
    Property:
      name: log-dir
      value: "logs"

  Appenders:
    RollingFile:
      name: RollingFile_Appender
      fileName: ${log-dir}/logfile.log
      filePattern: "${log-dir}logfile-%d{yyyy-MM-dd}.%i.txt"
      PatternLayout:
        pattern: "%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{35} - %msg%n"
      immediateFlush: false
        
      Policies:
        SizeBasedTriggeringPolicy:
          size: "10 MB"
        TimeBasedTriggeringPolicy:
          Interval: 1
          modulate: true
      DefaultRollOverStrategy:
        max: 10
        Delete:
          basePath: "${log-dir}"
          maxDepth: "1"
          IfLastModified:
            age: "P7D"
  
  Loggers:
    Root:
      level: info
      AppenderRef:
        ref: RollingFile_Appender
    Logger:
      name: dandi.dandi
      additivity: false
      level: debug
      includeLocation: false
      AppenderRef:
        ref: RollingFile_Appender

RollingFileAppender 속성

immediateFlush: false
Policies:
  TimeBasedTriggeringPolicy:
    Interval: 1
    modulate: true
  SizeBasedTriggeringPolicy:
    size: "10 MB"

immediateFlush

When set to true - the default, each write will be followed by a flush. This will guarantee that the data is passed to the operating system for writing.
Note that if this flag is set to false, and the logging activity is sparse, there may be an indefinite delay in the data eventually making it to the operating system, because it is held up in a buffer.

바로 Flush 할지에 대한 여부입니다. false로 두어야 Async 방식으로 Buffer를 통해 로그를 남길 수 있습니다.

TimeBasedTriggeringPolicy

Interval

How often a rollover should occur based on the most specific time unit in the date pattern. For example, with a date pattern with hours as the most specific item and increment of 4 rollovers would occur every 4 hours. The default value is 1.

시간 단위에 따라, 얼마나 자주 rollover를 발생시킬지 입니다. yyyy-MM-dd면 일 단위, yyyy-MM-dd-hh-mm면 분 단위가 됩니다.

현재 저는 date pattern을 yyyy-MM-dd로 사용하고 있고 interval을 1로 주었기 때문에 하루마다 rollover가 발생합니다.

modulate

Indicates whether the interval should be adjusted to cause the next rollover to occur on the interval boundary. For example, if the item is hours, the current hour is 3 am and the interval is 4 then the first rollover will occur at 4 am and then next ones will occur at 8 am, noon, 4pm, etc. The default value is false.

다음 rollover가 interval boundary에서 발생하도록 interval을 조정해야 하는지에 대한 것입니다.

예를 들어, Application이 13시 10분에 실행되었고 interval은 1시간 modulate가 false라면 다음 rollover는 14시 10분에 일어납니다. 하지만, modulate를 true로 지정한다면 다음 rollover는 14시에 일어납니다.

SizeBasedTriggeringPolicy

The SizeBasedTriggeringPolicy causes a rollover once the file has reached the specified size. (중략) When combined with a time based triggering policy the file pattern must contain a %i otherwise the target file will be overwritten on every rollover as the SizeBased Triggering Policy will not cause the timestamp value in the file name to change.

파일이 특정 크기에 다다르면 rollover를 발생시키는 설정입니다. TimeBasedTriggeringPolicy와 사용할 때 주의점이 있습니다. File Pattern에 %i가 존재하지 않는다면 SizedBasedTriggering rollover가 발생해도 rollover되는 것이 아니라 덮어쓰기가 발생합니다.

DefaultRollOverStrategy:
  max: 10
  Delete:
    basePath: "${log-dir}"
    maxDepth: "1"
    IfLastModified:
      age: "P7D"

max

The maximum value of the counter. Once this values is reached older archives will be deleted on subsequent rollovers. The default value is 7.

counter의 최대값. counter가 max 값을 도달하면 가장 오래된 파일이 삭제됩니다. default 값이 7입니다.

Delete

삭제 관련 설정을 할 수 있습니다.

basePath

Required. Base path from where to start scanning for files to delete.

삭제할 파일 scan을 어디서 할지에 대한 Base Path입니다.

maxDepth

The maximum number of levels of directories to visit.

디렉토리 깊이 제한입니다.

IfLastModified.age

Required. Specifies a duration. The condition accepts files that are as old or older than the specified duration.

age에 적힌 기간보다 오랜 파일을 삭제하는 조건입니다. 7일로 설정했습니다.

Logger 설정

AsyncLogger

Log4j2를 공식 문서에 의하면 아래처럼 스레드 수가 늘어감에 따라 더 좋은 성능을 보이는 AsyncLogger를 권장하고 있습니다.

AsyncLogger의 trade-off

하지만, AsyncLogger가 무작정 좋은 것은 아닙니다.

장점

  • Sync Logger에 비해 6 ~ 68배 빠른 성능
  • 대용량 로깅에 적합(로깅을 동기로 처리하기 않기 때문에 많은 로그 요청에도 application이 느려지는 것을 방지)

단점

  • 로깅 처리 과정에 예외가 발생하여 로깅에 실패했을 때, 비동기로 처리하기 때문에 문제 상황을 Application에 알리기 힘듦.
  • 새로운 스레드를 계속 생성해야하기 때문에, CPU 자원이 부족한 하드웨어에서는 성능 이점이 없을 수 있음

저는 1번째 단점이 신경쓰였습니다. 비즈니스적으로 중요한 로그의 경우에 누락될 경우에 큰 문제이기 때문입니다.따라서, 공식문서를 더 찾아보았고, 동기 + 비동기 방식을 사용할 수 있다는 점을 알았고 해당 방식을 채택하기로 결정했습니다.

Async + Sync Logger

공식문서에 따라, 아래 처럼 설정하면 됩니다. Root Logger는 동기 방식으로 등록해두고 AsyncLogger를 따로 등록해줍니다.

Configuration:
	Loggers:
    Root:
      level: info
      AppenderRef:
        - ref: RollingFile_Appender
    AsyncLogger:
      name: asyncLogger
      additivity: false
      level: debug
      includeLocation: false
      AppenderRef:
        - ref: RollingFile_Appender

그리고 사용처에서 아래처럼 비동기로 기록하려면 asyncLogger. asyncLogger가 아닌 다른 이름으로 getLogger를 하시면 됩니다.

Logger asyncLogger = LoggerFactory.getLogger("asyncLogger");
Logger synclogger = LoggerFactory.getLogger(TestController.class);

동기/비동기 Logger 테스트

잘 작동하는지 테스트를 한번해보았는데요. 아래와 같은 코드를 실행하면 잘 실행되는 것을 확인할 수 있습니다.

public void a() {
    for (int i = 0; i < 50; i++) {
        asyncLogger.info("abc");
    }
    logger.info("done");
}
// ...
2023-08-11 16:13:19.625 [http-nio-8080-exec-1] INFO  asyncLogger - abc
2023-08-11 16:13:19.625 [http-nio-8080-exec-1] INFO  asyncLogger - abc
2023-08-11 16:13:19.626 [http-nio-8080-exec-1] INFO  dandi.dandi.TestController - done
2023-08-11 16:13:19.625 [http-nio-8080-exec-1] INFO  asyncLogger - abc
2023-08-11 16:13:19.625 [http-nio-8080-exec-1] INFO  asyncLogger - abc
// ...

Garbage Free Mode

https://logging.apache.org/log4j/2.x/manual/garbagefree.html

Log4j2에서 GC를 최소화하는 기능입니다.

다른 Logging 라이브러리들에서는 로깅에 사용되는 객체들이 곧바로 GC의 대상이 되어 GC 발생률을 높입니다. 하지만, Log4j2는 최대한 GC의 대상이 되는 temporary 성향의 객체들을 최소화하고 생성된 객체들은 재사용하는 방식으로 동작합니다. 2.6 버전부터 Garbage Free가 Default니 버전을 선택하실 때 참고하시면 좋을 것 같습니다.

현재 저는 2.6 이상이 아닌, spring-boot-starter-log4j2의 2.17.2 를 사용하고 있어서 Garbage Free Mode 설정을 따로 해줘야합니다. 실행할 때 아래 옵션을 주면 됩니다.

-Dlog4j2.enable.threadlocals=true -Dlog4j2.enable.direct.encoders=true

ThreadLocals

objects are stored in ThreadLocal fields and reused

enableDirectEncoders

log events are converted to text and this text is converted to bytes without creating temporary objects

이렇게 로깅 설정을 마무리했습니다.

참고 자료

https://logging.apache.org/log4j/2.x/manual

https://stackify.com/compare-java-logging-frameworks/

https://velog.io/@stella6767/logback-spring.xml-설정방법

https://xlffm3.github.io/spring & spring boot/async-logger-performance/

사진 출처

https://logging.apache.org/log4j/2.x/

profile
공병주(Chris)
self-motivation
이전 포스트

Swagger(feat. Springdoc OpenAPI)

다음 포스트

Connection Timeout과 Read Timeout은 어떤 값이 적절할까?

0개의 댓글