Icednut's Note

Logback & SLF4J를 쓰면서 만났던 문제

2016-07-15

최근 Oozie에서 RabbitMQ로 메세지를 전송하는 Common Action 개발을 맡았다. 여기서 Action은 Spring Boot 기반으로 개발하고 있었는데 문제는 Spring Boot가 실행되면서 Logging 관련 라이브러리가 말썽을 일으켜 Spring Boot가 아예 실행조차 되질 않는 상황이 발생했다. 상황을 자세히 설명하자면 다음과 같다.

상황

  • Oozie에서 Executable Jar를 실행하는 Action이 하나 있었다.
  • 그런데 이 Jar파일은 Spring Boot Application 이었고, Jar 파일 안에는 관련 있는 디펜던시 라이브러리들이 모두 한데 묶여 포함되어 있었다. (한마디로 Fat Jar)
  • 디펜던시 중에는 Logback-core-1.1.3, Logback-classic-1.1.3, Slf4j-api-7.1.13이 있었고, 하필 Oozie 클러스터에 Slf4j-log4j2가 존재하고 있었다.

    1
    // TODO: 간략한 Dependency Tree 표기할 것
  • 다시 Spring Boot로 초점을 맞춰보면, Spring Boot가 Bootstraping 하면서 여러 Spring Event를 발생시키게 되는데 그 중에 하나가 org.springframework.boot.logging.LoggingApplicationListener이다.

  • 여기서 LoggingApplicationListener가 ApplicationStartedEvent를 핸들링 할 때 발생하는데, ApplicationStartedEvent를 받으면 LoggingSystem의 구현체를 결정하고 그 구현체를 초기화하는 로직이 실행되게 된다.

    1
    2
    3
    4
    private void onApplicationStartedEvent(ApplicationStartedEvent event) {
    this.loggingSystem = LoggingSystem.get(event.getSpringApplication().getClassLoader());
    this.loggingSystem.beforeInitialize();
    }
  • 문제는 LoggingSystem의 구현체를 결정할 때(LoggingSystem.get 메소드를 호출할 때) 현재 디펜던시 상황에 따라 LogbackLoggingSystem이 결정되고 초기화가 진행되는데 초기화 진행 중 StaticLoggerBinder에게 LoggerContext를 요청한 뒤 요청 결과물을 LoggerContext로 캐스팅을 진행할 때 결과물이 Log4jLoggerFactory라고 인식이 되어 캐스팅 불가능하게 되어 예외가 발생하며 시스템이 실행되질 않는다.

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    private LoggerContext getLoggerContext() {
    ILoggerFactory factory = StaticLoggerBinder.getSingleton().getLoggerFactory();
    Assert.isInstanceOf(LoggerContext.class, factory,
    String.format(
    "LoggerFactory is not a Logback LoggerContext but Logback is on "
    + "the classpath. Either remove Logback or the competing "
    + "implementation (%s loaded from %s). If you are using "
    + "WebLogic you will need to add 'org.slf4j' to "
    + "prefer-application-packages in WEB-INF/weblogic.xml",
    factory.getClass(), getLocation(factory)));
    return (LoggerContext) factory;
    }
  • 뭔소리인지 소스코드와 함께 다시 설명하자면 StaticLoggerBinder.getSingleton().getLoggerFactory()의 결과물이 Logback의 LoggerContext가 아니라 Slf4j-log4j2의 Log4jLoggerFactory가 반환된다는 소리이다.

왜 이런 문제가 발생하는 것일까?
앞에서도 이미 말했지만 Logback과 Slf4j-log4j2에 각각 존재하는 StaticLoggerFactory의 구현체가 서로 다르기 때문에 발생하는 문제이다. 사실 java의 Logging 라이브러리를 조금 유심히 살펴본 사람이라면 금방 알아차릴 수 있는 문제이긴 하지만, 모르더라도 Logback과 Slf4j의 소스코드를 살펴보면 구현체가 뭐가 다른지를 알 수 있다. 그럼 어떻게 해결해야 될까?

위 문제의 원인을 요약하자면 다음과 같다.

  • Oozie 클러스터에 있는 slf4j-log4j2 라이브러리 때문에 Spring boot에서 Logback과 오류를 일으킨다.
  • 문제는 Logback이 아니라 Spring boot에서 logback과 slf4j-log4j2를 같이 쓰면 오류를 발생시키는게 문제이다.

해결

  • spring boot를 안쓰거나 (LoggingApplicationListener만 등록 안하게 하는 것도 방법일 것 같다.)
  • logback을 안쓰거나 (Logback을 안쓰고 Slf4j-log4j2를 쓰게 만드는 전략)
  • slf4j-log4j2의 LoggerFactory가 인식되기 전에 logback-classic의 LoggerFactory가 인식되게 해야 한다. (아니면 StaticLoggerBinder가 강제로 Logback의 것으로 하게 한다던가..)

일단 가장 간단한 해결 방법은 Logback을 안쓰는 방법이다. 그런데 그렇게하면 더 이상 파일이나 Standard Output (System.out)으로 로그를 볼 수 없다.
그럼 로그도 정상적으로 출력되면서 라이브러리 충돌도 안일으키게 하려면 어떻게 해야될까?

그 외 앞으로 할 일…

이번 문제가 어느 정도 해결이 되고 나면 Java의 Logging 라이브러리를 좀 더 연구해봐야 겠다. Logback과 Slf4j의 공식 사이트가서 영어 까막눈이 레퍼런스를 들여다봐도 장님 코끼리 더듬는 느낌이다…

Tags: Logback SLF4J oozie