log4j：log4j2日志备份日期错误

问题描述：

    最近项目上发现线上服务的日志备份出现了问题：有一台机器上7号的备份文件里面写的是8号的日志，8号的备份文件里面写的是9号的日志。。。其他机器上的日志正常。日志的备份相关的配置如下：

appender.R.type=RollingFile
appender.R.name=R
appender.R.fileName=/home/servlets/logs/dialogue.log
appender.R.filePattern=/home/servlets/logs/dialogue.log.%d{yyyy-MM-dd}
appender.R.layout.type=PatternLayout
appender.R.layout.pattern=%d [%t] %-5p %c{2} - %X{msgId} - %m%n
appender.R.strategy.type=DefaultRolloverStrategy
appender.R.strategy.max=5
appender.R.policies.type=policies
appender.R.policies.time.type=TimeBasedTriggeringPolicy
appender.R.policies.time.interval=1

问题分析：

1、系统时间检查

    看起来很像是服务器的锅，所以想要去检查机器的时间是不是有问题。登录不了线上机器，貌似要找运维。。。。还是自己先看看有没有解决办法吧。

    看配置文件：

appender.R.layout.pattern=%d [%t] %-5p %c{2} - %X{msgId} - %m%n

    其中，%d表示打印时间。所以，如果log4j2的时间是取自机器时间的话，是不是就可以判断机器的时间是不是有问题呢？log4j2获取时间的操作封装在DateLookup中：

    public String lookup(final String key) {
        return formatDate(System.currentTimeMillis(), key);
    }

    可以看到，每一条log中打印的时间，都是取自系统时间。可以判断，服务器的时间没有问题。

2、线下复现问题

模拟线上环境尝试复现问题：

    既然不是服务器的锅，那就说明在线下这个问题是可以复现的。

    首先在本地复现线上的环境（将本地的环境设置成生产环境），排除无关变量；然后启动服务，尝试复现问题。为了保证尽快解决问题，修改日志备份的粒度，每分钟备份一次：

appender.R.filePattern=/home/servlets/logs/dialogue.log.%d{yyyy-MM-dd-HH-mm}

    启动服务，并模拟用户的业务请求，保证日志不断；10分钟后重启服务，并不断请求业务；多次重复前面步骤。观察日志，发现，问题偶现。

使用线下环境尝试复现问题：

    将本地环境恢复成测试环境，重复上面的操作，问题不出现。

    这里可以推测：

1）问题确实和服务器无关；

2）问题的出现有一定的偶然因素（不是每台服务器都出了问题，也不是每次线下复现的时候都出了问题）；

3）问题出现后往往连续出现，不出现的时候往往也是连续正常备份。结合线上服务器只有一台出问题，且该服务器上大多数日志备份都出问题的情况，推测偶然因素大概率出现在服务启动或者初始化的过程中。

4）使用测试环境问题多次尝试并不会复现，推测：问题出现的原因，来自于线上环境和线下环境初始化过程中，有差异的部分中中包含偶然因素的部分。

问题定位：

操作：

    根据上述问题分析代码，发现问题可能在于线上环境会多加载一份log4j1的配置文件。推测偶然因素是log4j2和log4j1配置文件加载的先后顺序导致的。

    使用ScheduledExecutorService控制不同log4j日志加载的顺序，例如可以设置时间差为3s。例如，先加载log4j1的配置，可以按如下写法：

    ScheduledExecutorService service = Executors.newScheduledThreadPool(2);

    Runnable log4jInit = () -> {
      String logConfigFile = "polaris/properties/log4j_config.properties";
      PropertyConfigurator.configure(logConfigFile);
    };

    Runnable log4j2Init = () -> {
      URL urlLog4j2 = DialogueLogUtil.class.getClassLoader()
          .getResource("log4j2_config.properties");
      ConfigurationSource source = null try {
        source = new ConfigurationSource(url.openStream(), urlLog4j2);
      } catch (IOException e) {
        e.printStackTrace();
      }
      Configurator.initialize(null, source);
    };
    
    service.schedule(log4jInit, 0, TimeUnit.SECONDS);
    service.schedule(log4j2Init, 3, TimeUnit.SECONDS);

    分别测试在先加载log4j1的配置和先加载log4j2配置的情况下，日志备份的情况。

现象：

1）先加载log4j1的配置，延迟3s加载log4j2的配置，现象：日志备份异常，log4j1的日志异常打印到了前1分钟的备份日志中，log4j2的日志正常打印到了dialogue.log中，问题和线上的问题相反。由于log4j1的日志级别是error，且日志极少，一天不一定会出现一条，所以在这种情况下线上日志看起来正常；

2）先加载log4j2的配置，延迟3s加载log4j1的配置，现象：日志备份异常，log4j2的日志异常打印到了前1分钟的备份日志中，log4j1的日志正常打印到了dialogue.log中，现象和线上的问题相似。

总结：

    进行到这里，可以判断，确实是两套log同时操作一个日志文件导致的异常。

问题解决：

    移除将log4j1配置文件中打印到文件的appender配置，或者将log4j1的日志文件指向另一个不同的文件。

总结：

    两套log同时操作一个日志文件可能会导致日志写入异常，出现日志备份文件中的日志日期和备份文件的日期不一致的情况。