Java Hbase-client 디펜던시 추가 후 로그가 제대로 안나오는 이슈 (with Slf4j, Logback)

Wan Geun Lee / July 09, 2019

이슈: hbase-client 디펜던시를 추가하면 로그가 안나옴

최근 logback을 사용하고 있는 스칼라 Akka 프로젝트에서 hbase를 연동할 일이 있어서 hbase-shaded-client 디펜던시 추가 후 hbase 관련 데이터 조회 및 저장 작업을 진행하게 되었다.

Groovy
0
1
2
3
4
5
6
7
// build.sbt
libraryDependencies ++= {
  ...,
  "com.typesafe.akka" %% "akka-slf4j" % akkaVersion,
  "com.typesafe.scala-logging" %% "scala-logging" % scalaLoggingVersion,
  "ch.qos.logback" % "logback-classic" % "1.1.7",
  "org.apache.hbase" % "hbase-shaded-client" % hbaseClientVersion // highlight-line
}

그런데 위 디펜던시를 추가한 순간 콘솔에 로그가 나오질 않았다. 정확하게는 org.slf4j.Logger로 출력한 내용은 나오질 않고 System.out.print로 출력한 코드만 나오고 있었다.

Plain Text
0
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
// 서버 로그 

/Library/Java/JavaVirtualMachines/jdk1.8.0_201.jdk/Contents/Home/bin/java ...
Connected to the target VM, address: '127.0.0.1:55918', transport: 'socket'
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/Users/xxx/.ivy2/cache/org.slf4j/slf4j-log4j12/jars/slf4j-log4j12-1.7.5.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/Users/xxx/.ivy2/cache/ch.qos.logback/logback-classic/jars/logback-classic-1.1.7.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]
log4j:WARN No appenders could be found for logger (com.xxx.DatabaseSupport$).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.
Java config name: ***
Loaded from Java config
Java config name: ***
Loaded from Java config
>>> KdcAccessibility: reset
>>> KdcAccessibility: reset
...

근데 또 어떨 때는 slf4j-log4j12/StaticLoggerBinder와 logback/StaticLoggerBinder의 로딩 순서가 서로 바뀌면서 로딩이 되면서 로그가 나오는 경우도 있었다. (허허…)

Plain Text
0
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
// 서버 로그

/Library/Java/JavaVirtualMachines/jdk1.8.0_201.jdk/Contents/Home/bin/java ...
Connected to the target VM, address: '127.0.0.1:56170', transport: 'socket'
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/Users/xxx/.ivy2/cache/ch.qos.logback/logback-classic/jars/logback-classic-1.1.7.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/Users/xxx/.ivy2/cache/org.slf4j/slf4j-log4j12/jars/slf4j-log4j12-1.7.5.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [ch.qos.logback.classic.util.ContextSelectorStaticBinder]
[xxx-macbook.local:2019-07-10 11:23:21] INFO [com.xxx.DatabaseSupport$:<init>:14] initializing database mysql
[xxx-macbook.local:2019-07-10 11:23:21] WARN [slick.basic.DatabaseConfig:warn:25] Use `mysql.profile` instead of `mysql.driver`. The latter is deprecated since Slick 3.2 and will be removed.
[xxx-macbook.local:2019-07-10 11:23:21] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:841] mysql.db - configuration:
[xxx-macbook.local:2019-07-10 11:23:21] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:857] allowPoolSuspension.............false
[xxx-macbook.local:2019-07-10 11:23:21] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:857] autoCommit......................true
[xxx-macbook.local:2019-07-10 11:23:21] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:857] catalog.........................null
[xxx-macbook.local:2019-07-10 11:23:21] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:857] connectionInitSql...............null
[xxx-macbook.local:2019-07-10 11:23:21] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:857] connectionTestQuery.............null
[xxx-macbook.local:2019-07-10 11:23:21] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:857] connectionTimeout...............1000
[xxx-macbook.local:2019-07-10 11:23:21] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:857] dataSource......................null
[xxx-macbook.local:2019-07-10 11:23:21] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:857] dataSourceClassName.............null
[xxx-macbook.local:2019-07-10 11:23:21] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:857] dataSourceJNDI..................null
...

 

해결

구글에서 좀 찾아보니 hbase-client 추가 후 로그가 안나올 경우 slf4j, log4j 디펜던시를 exclude 해보라는 글이 보였다. (https://kimfish.co.kr/285) 그래서 아래와 같이 slf4j와 log4j 디펜던시를 제외한 후 어플리케이션을 재시작해보니 로그가 정상적으로 나왔다. 심지어 StaticLoggerBinder 클래스를 여러 개 찾았다는 로그도 보이질 않았다.

Groovy
0
1
2
3
4
5
6
7
8
9
10
// build.sbt
libraryDependencies ++= {
  ...,
  "com.typesafe.akka" %% "akka-slf4j" % akkaVersion,
  "com.typesafe.scala-logging" %% "scala-logging" % scalaLoggingVersion,
  "ch.qos.logback" % "logback-classic" % "1.1.7",
  "org.apache.hbase" % "hbase-shaded-client" % hbaseClientVersion excludeAll( // highlight-line
    ExclusionRule(organization = "org.slf4j", name = "slf4j-log4j12"), // highlight-line
    ExclusionRule(organization = "log4j", name = "log4j") // highlight-line
  ) // highlight-line
}
Plain Text
0
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
// 서버 로그

/Library/Java/JavaVirtualMachines/jdk1.8.0_201.jdk/Contents/Home/bin/java ...
Connected to the target VM, address: '127.0.0.1:56047', transport: 'socket'
[xxx-macbook.local:2019-07-10 11:17:52] INFO [com.xxx.DatabaseSupport$:<init>:14] initializing database mysql
[xxx-macbook.local:2019-07-10 11:17:52] WARN [slick.basic.DatabaseConfig:warn:25] Use `mysql.profile` instead of `mysql.driver`. The latter is deprecated since Slick 3.2 and will be removed.
[xxx-macbook.local:2019-07-10 11:17:53] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:841] mysql.db - configuration:
[xxx-macbook.local:2019-07-10 11:17:53] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:857] allowPoolSuspension.............false
[xxx-macbook.local:2019-07-10 11:17:53] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:857] autoCommit......................true
[xxx-macbook.local:2019-07-10 11:17:53] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:857] catalog.........................null
[xxx-macbook.local:2019-07-10 11:17:53] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:857] connectionInitSql...............null
[xxx-macbook.local:2019-07-10 11:17:53] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:857] connectionTestQuery.............null
[xxx-macbook.local:2019-07-10 11:17:53] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:857] connectionTimeout...............1000
[xxx-macbook.local:2019-07-10 11:17:53] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:857] dataSource......................null
[xxx-macbook.local:2019-07-10 11:17:53] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:857] dataSourceClassName.............null
[xxx-macbook.local:2019-07-10 11:17:53] DEBUG [com.zaxxer.hikari.HikariConfig:logConfiguration:857] dataSourceJNDI..................null
...
Java config name: ***
Loaded from Java config
Java config name: ***
Loaded from Java config
>>> KdcAccessibility: reset
>>> KdcAccessibility: reset
...

 

왜 그런걸까?

답은 이미 로그에 나와있다. 먼저 첫 번째 서버 로그를 살펴보면 slf4j-log4j12의 StaticLoggerBinder가 먼저 로딩되고 있었다.

Plain Text
0
1
2
3
4
5
6
7
8
9
10
11
12
// 서버 로그 

/Library/Java/JavaVirtualMachines/jdk1.8.0_201.jdk/Contents/Home/bin/java ...
Connected to the target VM, address: '127.0.0.1:55918', transport: 'socket'
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/Users/xxx/.ivy2/cache/org.slf4j/slf4j-log4j12/jars/slf4j-log4j12-1.7.5.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/Users/xxx/.ivy2/cache/ch.qos.logback/logback-classic/jars/logback-classic-1.1.7.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]
log4j:WARN No appenders could be found for logger (com.xxx.DatabaseSupport$).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.
...

문제는 slf4j-log4j12의 로그 바인더가 로딩이 되었지만 프로젝트에는 로그 출력에 대한 설정이 없기 때문에 로그 출력이 되질 않았던 것이다. 두 번째 서버 로그에는 다행히도 logback의 로그 바인더가 먼저 로딩이 되었고 프로젝트에는 이미 logback 관련 서버 로그 출력 설정이 되어 있어서 서버 로그가 출력이 되고 있었다.

Plain Text
0
1
2
3
4
5
6
7
8
9
// 서버 로그

/Library/Java/JavaVirtualMachines/jdk1.8.0_201.jdk/Contents/Home/bin/java ...
Connected to the target VM, address: '127.0.0.1:56170', transport: 'socket'
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/Users/xxx/.ivy2/cache/ch.qos.logback/logback-classic/jars/logback-classic-1.1.7.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/Users/xxx/.ivy2/cache/org.slf4j/slf4j-log4j12/jars/slf4j-log4j12-1.7.5.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [ch.qos.logback.classic.util.ContextSelectorStaticBinder]
...
XML
0
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
<!-- logback.xml -->
<configuration>
    <appender name="APPLICATION" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <File>${LOG_PATH}/application.log</File>
        <encoder>
            <pattern>[${HOSTNAME}:%d{yyyy-MM-dd HH:mm:ss}] %level [%logger:%method:%L] %replace(%msg){'\n', ' '}%n</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_PATH}/application.%d{yyyy-MM-dd}.log</fileNamePattern>
        </rollingPolicy>
    </appender>
    <logger name="akka" level="info" additivity="false">
        <appender-ref ref="APPLICATION"/>
    </logger>
    <root level="info">
        <appender-ref ref="APPLICATION"/>
    </root>
</configuration>

로깅 구현체 디펜던시가 2개라서 로그 바인더가 둘 중 하나만 선택 된다는 것은 이해가 가는데 로그 바인더의 로딩 순서가 왜 상황에 따라 다른 것일까? 로딩 순서를 알기 위해서는 로그 바인더의 로딩 과정을 살펴볼 필요가 있다.

 

Slf4j의 로그 바인더 로딩 과정

logback이나 log4j를 보면 항상 따라오는 디펜던시가 있는데 바로 slf4j-api라는 디펜던시이다. slf4j는 Simple Logging Facade for Java의 약자로 다양한 로깅 프레임워크(ex: java.util.logging, logback, log4j)에 대한 추상화 퍼사드를 제공한다. 따라서 slf4j-api 라는 퍼사드만 사용하게 되면 구현체(ex: java.util.logging, logback, log4j)는 어떤걸 쓰던지 상관없이 동일한 메소드로 로깅을 할 수 있게 된다.

An image from Notion

[출처: https://www.slf4j.org/manual.html]

위에 스크린샷은 slf4j 공식 홈페이지의 유저 메뉴얼에서 가져온 이미지인데 자세히 보면 Application에서는 모두 slf4j-api를 참조하고 있는 것을 볼 수 있다.

그럼 slf4j-api의 어떤 API를 통해서 로깅을 하게 되는 것일까? 이미 써본 사람은 알겠지만 org.slf4j.LoggerFactory 라는 클래스를 통해 Logger를 결정한 뒤 그렇게 결정된 Logger로 로깅을 하면 된다.

Java
0
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
package org.slf4j;

public final class LoggerFactory {

    static final int UNINITIALIZED = 0;
    static final int ONGOING_INITIALIZATION = 1;
    static final int FAILED_INITIALIZATION = 2;
    static final int SUCCESSFUL_INITIALIZATION = 3;
    static final int NOP_FALLBACK_INITIALIZATION = 4;

    static volatile int INITIALIZATION_STATE = UNINITIALIZED;

    private LoggerFactory() {
    }

    ...

    public static Logger getLogger(String name) {
        ILoggerFactory iLoggerFactory = getILoggerFactory();// highlight-line
        return iLoggerFactory.getLogger(name);
    }

    public static Logger getLogger(Class<?> clazz) {
        Logger logger = getLogger(clazz.getName());// highlight-line
        if (DETECT_LOGGER_NAME_MISMATCH) {
            Class<?> autoComputedCallingClass = Util.getCallingClass();
            if (autoComputedCallingClass != null && nonMatchingClasses(clazz, autoComputedCallingClass)) {
                Util.report(String.format("Detected logger name mismatch. Given name: \"%s\"; computed name: \"%s\".", logger.getName(),
                                autoComputedCallingClass.getName()));
                Util.report("See " + LOGGER_NAME_MISMATCH_URL + " for an explanation");
            }
        }
        return logger;
    }

    ...

    public static ILoggerFactory getILoggerFactory() {
        if (INITIALIZATION_STATE == UNINITIALIZED) {
            synchronized (LoggerFactory.class) {
                if (INITIALIZATION_STATE == UNINITIALIZED) {
                    INITIALIZATION_STATE = ONGOING_INITIALIZATION;
                    performInitialization();// highlight-line
                }
            }
        }
        switch (INITIALIZATION_STATE) {
        case SUCCESSFUL_INITIALIZATION:
            return StaticLoggerBinder.getSingleton().getLoggerFactory();
        case NOP_FALLBACK_INITIALIZATION:
            return NOP_FALLBACK_FACTORY;
        case FAILED_INITIALIZATION:
            throw new IllegalStateException(UNSUCCESSFUL_INIT_MSG);
        case ONGOING_INITIALIZATION:
            // support re-entrant behavior.
            // See also http://jira.qos.ch/browse/SLF4J-97
            return SUBST_FACTORY;
        }
        throw new IllegalStateException("Unreachable code");
    }

    private final static void performInitialization() {
        bind();// highlight-line
        if (INITIALIZATION_STATE == SUCCESSFUL_INITIALIZATION) {
            versionSanityCheck();
        }
    }

    private final static void bind() {
        try {
            Set<URL> staticLoggerBinderPathSet = null;

            ...

            StaticLoggerBinder.getSingleton(); // highlight-line
            INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
            reportActualBinding(staticLoggerBinderPathSet);
            fixSubstituteLoggers();
            replayEvents();

            SUBST_FACTORY.clear();
        } catch (NoClassDefFoundError ncde) {
            String msg = ncde.getMessage();
            if (messageContainsOrgSlf4jImplStaticLoggerBinder(msg)) {
                ...
            } else {
                ...
                throw ncde;
            }
        } catch (java.lang.NoSuchMethodError nsme) {
            ...
            throw nsme;
        } catch (Exception e) {
            ...
            throw new IllegalStateException("Unexpected initialization failure", e);
        }
    }

}

LoggerFactory의 getLogger 메소드들을 살펴보면 getILoggerFactory 메소드를 호출하는 것을 볼 수 있다. 또 getILoggerFactory 안에는 performInitialization > bind 메소드를 호출하고 있는데 bind 메소드 안에는 StaticLoggerBinder.getSingleton() 메소드를 호출하고 있다. 이 때 로깅 구현체의 StaticLoggerBinder가 결정되어 로딩되게 된다.

그럼 프로젝트에 로깅 구현체 여러 개일 경우 StaticLoggerBinder.getSingleton() 메소드 호출 시 결정되는 로깅 구현체는 어떤 것이 되는 것일까? 그것은 아직 추측이지만 JVM에서 로깅 구현체 디펜던시 인식 순서에 따라 로깅 구현체를 어떤 것을 할지 결정되는 것 같다.

 

결론

  • 자바에서 로깅은 slf4j-api라는 로깅 퍼사드라는 추상화된 로깅 메소드를 사용하여 로깅을 진행한다.
  • slf4j-api는 로깅 구현체가 있어야지만 로그를 남길 수 있다.
  • 로깅 구현체는 프로젝트에 셋팅한 로그 설정 파일에 맞는 로깅 구현체를 사용하도록 하자.