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）。