一个进程里两处日志时间时区不一样的问题

    最近发现一个进程里打出来的日志里时区不一样，一个是UTC时间,2018-09-12 10:48:12.278,一个是北京时间2018-09-12 18:48:15.453。北京时间的是log4j输出的,UTC时间的是我们自己输出的，我们自己的时间字符串来源是大概如下两行代码:

SimpleDateFormat dateFormat = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");
String dateString = dateFormat.format(new Date());

Log4j的时间是怎么来的呢?
以log4j1为例,有如下调用关系 
RollingFileAppender.subAppend()->WriterAppender.subAppend()-> PatternLayout.format() -> BridgePatternConverter.format() -> FormattingInfo.format() -> DatePatternConverter.format() -> CachedDateFormat.format()
那CachedDateFormat是怎么初始化的呢? DatePatternConverter 构造方法中可以看到

    if ((options != null) && (options.length > 1)) {
      TimeZone tz = TimeZone.getTimeZone((String) options[1]);
      simpleFormat.setTimeZone(tz);
    } else {
      simpleFormat = new DefaultZoneDateFormat(simpleFormat);
    }
    df = new CachedDateFormat(simpleFormat, maximumCacheValidity);

可以在log4j.xml中指定时区(比如"%d{ISO8601}{GMT-4}  %m%n"),如果不指定则是使用操作系统默认时区

log4j2中则是
RollingFileAppender.append() -> AbstractOutputStreamAppender.append() -> AbstractOutputStreamAppender.tryAppend() -> AbstractOutputStreamAppender.writeByteArrayToManager() -> AbstractStringLayout.toByteArray() -> PatternLayout.toSerializable() -> PatternLayout.PatternSerializer.toSerializable()->PatternLayout.PatternSerializer.toSerializable() -> PatternFormatter.format() —> DatePatternConverter.format()—> DatePatternConverter.formatWithoutAllocation()
在DatePatternConverter 类的 createNonFixedFormatter 可以看到

        TimeZone tz = null;
        if (options.length > 1 && options[1] != null) {
            tz = TimeZone.getTimeZone(options[1]);
        }

        try {
            final FastDateFormat tempFormat = FastDateFormat.getInstance(pattern, tz);
            return new PatternFormatter(tempFormat);

在不设置tz的情况下 timeZone = TimeZone.getDefault();
FormatCache 来cache每种类型;
不论log4j1还是log4j2,可以确定如下几点:
1.如果不配置时区,都是使用默认时区
2.时区初始化好了就不会变化
3.一个Appender对象一种格式化对象(log4j2是FastDateFormat对象;log4j1是DefaultZoneDateFormat)

 

回到问题,我们自己的和logj对时间的时区处理都是基于TimeZone.getDefault()来的,为什么会一个是UTC一个是CST呢？
后来定位到是因为我们自己自己懒加载的bean里有静态块
TimeZone.setDefault(TimeZone.getTimeZone("UTC"));
那么问题就清楚了,log4j的LOGGER和Appender对象初始化时先读取了操作系统的CST时间,然后对象一直没变；然后我们代码修改了时区,导致我们代码打出来的时间为UTC。