Log4j2 在 Windows 下致使 System.out 失效

此問題已經在 Log4j2 2.3 裏面修復，詳見 https://issues.apache.org/jira/browse/LOG4J2-965

今天在 Windows 下調試這幾天寫的一個命令行程序，發如今 Log4j2 在一種狀況下會在 Windows 下會出現 System.out.println("XXXX") 沒法輸出到終端的狀況，花了幾個小時去排查這個問題，這裏分享一下。

1. 問題還原

爲了簡化問題，我儘可能用少的代碼來重現出這個 Bug，首先是工程的 build.gradle 文件：

apply plugin: 'java'

version = '1.0'

repositories {
    mavenCentral()
}

def log4j2Version = '2.2'
def log4j2GroupId = "org.apache.logging.log4j"

dependencies {
    compile log4j2GroupId + ':log4j-core:' + log4j2Version
    compile log4j2GroupId + ":log4j-jcl:" + log4j2Version
    compile log4j2GroupId + ":log4j-slf4j-impl:" + log4j2Version
    compile 'org.fusesource.jansi:jansi:1.11'
}

一個位於 src/main/resources 目錄下的 log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Appenders>
        <File name="root" fileName="${sys:user.home}/logs/windowsbug.log">
            <PatternLayout>
                <Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
            </PatternLayout>
        </File>
    </Appenders>
    <Loggers>
        <Root level="info">
            <AppenderRef ref="root"/>
        </Root>
    </Loggers>
</Configuration>

而後是重現問題的代碼：

import org.slf4j.LoggerFactory;

/**
 * @author khotyn 15/3/2 下午8:17
 */
public class Log4j2WindowsBug {

    public static void main(String[] args) {
        System.out.println("Able to print on Windows");
        LoggerFactory.getLogger(Log4j2WindowsBug.class);
        System.out.println("Unable to print on Windows");
    }
}

這段代碼在 Windows 下的運行結果是：

Able to print on Windows

在 getLogger 後面的那一句 System.out 並無輸出。

2. 問題緣由

剛開始遇到這個問題的時候很是震驚，由於以爲 System.out.println 應該是 Java 最基本的功能了，遇到這樣的問題，瞬間讓我以爲人生完整了。在通過一陣 Debug 之後，發現執行第三行代碼的時候，System.out 這個 PrintWriter裏面的 out 成員變量爲 null 了，而後就致使了 println 方法在檢查 out 是否爲 null 的時候拋了一個異常：

/** Checks to make sure that the stream has not been closed */
private void ensureOpen() throws IOException {
    if (out == null)
        throw new IOException("Stream closed");
}

那麼究竟是什麼把 out 給置爲 null 了呢。通過了一段時間的 Debug，發現了在 Windows 下，若是 ClassPath 下有 org.fusesource.jansi.WindowsAnsiOutputStream 這個類的話，Log4j2 會將用這個類將 System.out 包裝起來（按照 Log4j2 的說明，這是是爲了在 Windows 下的 Console 上支持彩色字符）：

而後，在 log4j2 裏面，無論在 ClassPath 下有沒有 log4j2.xml 或者方式的配置，它都會先初始化一個 ConsoleAppender，若是後面發現有諸如 log4j2.xml 這樣的配置，那麼就進行 reconfigure，咱們看下 log4j2 裏面的 LoggerContext 類的 reconfigure 方法：

主要看它所調用到的 setConfiguration 方法：

在這個方法裏面，若是發現以前有了配置（就是默認的 ConsoleAppender），就會嘗試關閉它，而後繼續跟蹤 prev.stop 這段代碼，發現它下面會走到 OutPutStreamManager 的這段代碼：

只有當 outputStream 是 System.out 或者 System.err 的時候，纔不會關閉，可是若是是 System.out 的封裝，就好比咱們這個場景中的 WindowsAnsiOutputStream，就被關閉了，進而致使後續的 System.out.println 都無效。

3. 解決方法

其實細心的話，在上面的截圖的代碼中就能夠看到解決方法了，要解決這個問題，只須要在 log4j2 初始化以前執行下面這段代碼

System.setProperty("log4j.skipJansi", true)

不過，這個方法只有像我這樣其實對於 log4j 時候採用 Jansi 的封裝無所謂的人才算有用。若是有所謂的話，那麼彷佛只能坐等官方修 Bug 了（https://issues.apache.org/jira/browse/LOG4J2-965）。