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