背景：
最近打算将主要几个项目配置负载均衡策略，由于当前业务用户不多，不存在并发流量问题，我们目的只是为了实现不停机部署以及进程级别的故障转移而已。

通过Jenkins动态传入端口选项参数，启动多实例项目，配合nginx的upstream策略将对应域名请求分发到不同端口。当然，首先我们得考虑项目中的服务状态以及资源共享问题，确保多实例部署不会对业务流程造成影响。

这些操作配置不难，重点还是在于要充分考虑同一项目多实例会不会带来新的问题。比如，这次我就没考虑到 日志共享 时的滚动问题。

---

---

一、问题来源

开发环境：

JDK：1.8
操作系统：CentOS 7.4
web框架：SpringBoot 1.5.9
日志框架：Logback 1.1.11

问题描述：

我们负载均衡的两个相同项目（端口9990和8099）是用的是同样的Logback配置，写入的日志名称以及滚定策略都是一模一样。

两个项目启动运行时都没问题，日志都是顺序合并打印在stdout.log文件中，但是在第二天00:00:00这个时间点后，两个项目都去尝试将之前一天的stdout.log改名为stdout.log.2019-10-28.log，然后再创建新的stdout.log。

最终结果是这样：
首先日志文件stdout.log和stdout.log.2019-10-28.log都是正常生成，8099端口这个项目正常在新的stdout.log中打印，但是9990端口的这个项目日志却在stdout.log.2019-10-28.log这个文件打印，并且2019-10-28这一天的日志内容（原stdout.log）消失了，也就是说stdout.log.2019-10-28.log现在只有9990端口29号的日志内容了，28号的日志文件都被覆盖了。

这种现象乍一看比较诡异，日志滚动过程中到底发生了什么导致这种现象发生呢？我们直接看源码来分析下吧！

注： 我在此强调一下，跟踪源码时不要太抠细节，我们接触的开源框架背后都是一个团队数年以上不停迭代更新的产物，蕴含大量的抽象层次、设计模式、功能模块、历史兼容等。我们一般只需要聚焦自己的关注点，慢慢展开分析，遇到看不懂的很正常，先不要深挖。

---

二、源码跟踪

在跟踪源码之前我们需要明确一点：

并不是每天到达0点时，项目就会自动去重命名备份旧日志，产生新的日志。而是每有一条日志打印时，都会去判断是否需要滚动，发现满足条件后才执行滚动操作。也就是第二天0点后的第一条日志打印时，此刻才会触发滚动操作。

项目Logback部分配置：

logback-spring.xml：

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <property name="LOG_PATH" value="/home/dev/log/xxx" />

    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <File>${LOG_PATH}/stdout.log</File>
        <encoder>
            <pattern>%date [%level] [%thread] %logger{60} [%file : %line] %msg%n</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- 添加.gz 历史日志会启用压缩 大大缩小日志文件所占空间 -->
            <fileNamePattern>${LOG_PATH}/stdout.log.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory><!--  保留30天日志 -->
        </rollingPolicy>
    </appender>

    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="FILE"/>
    </root>
</configuration>

上面只配置根节点Logger[ROOT]的打印级别（INFO）以及两个appender，所有类都按照其配置打印日志。

---

Debug入口：com.xxx.controller.xxxController：

private static final Logger logger = LoggerFactory.getLogger(this.getClass());

logger.info("Logback源码跟踪");

从logger.info方法开始debug。

ch.qos.logback.classic.Logger：

public void info(String msg) {
    filterAndLog_0_Or3Plus(FQCN, null, Level.INFO, msg, null, null);
}

private void filterAndLog_0_Or3Plus(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params,
                final Throwable t) {

    final FilterReply decision = loggerContext.getTurboFilterChainDecision_0_3OrMore(marker, this, level, msg, params, t);

    if (decision == FilterReply.NEUTRAL) {
        if (effectiveLevelInt > level.levelInt) {
            return;
        }
    } else if (decision == FilterReply.DENY) {
        return;
    }

    buildLoggingEventAndAppend(localFQCN, marker, level, msg, params, t);
}

private void buildLoggingEventAndAppend(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params,
                final Throwable t) {
    LoggingEvent le = new LoggingEvent(localFQCN, this, level, msg, t, params);
    le.setMarker(marker);
    callAppenders(le);
}

/**
 * Invoke all the appenders of this logger.
 * 
 * @param event
 *          The event to log
 */
public void callAppenders(ILoggingEvent event) {
    int writes = 0;
    // 这里会从Logger[com.xxx.controller.xxxController]（也就是logger.info入口所在类的Logger）一直往上遍历（Logger.parent）
    // 也就是从Logger[com.xxx.controller.xxxController] -> Logger[com.xxx.controller] -> Logger[com.xxx] -> Logger[com] -> Logger[ROOT]
    // 判断每一层Logger的aai属性是否不为空，aai指的是AppenderAttachableImpl，这是一个Appender的列表结构，可以包含多个Appender
    // 我们logback-spring.xml文件配置的各种Logger下的appender都存在于AppenderAttachableImpl中
    for (Logger l = this; l != null; l = l.parent) {
        writes += l.appendLoopOnAppenders(event);
        if (!l.additive) {
            break;
        }
    }
    // No appenders in hierarchy
    if (writes == 0) {
        loggerContext.noAppenderDefinedWarning(this);
    }
}

private int appendLoopOnAppenders(ILoggingEvent event) {
	// 由于我们只配置根节点Logger[ROOT]的appender，所以会一直遍历到Logger[ROOT]时aai才不为null，进入aai.appendLoopOnAppenders(event)方法
    if (aai != null) {
        return aai.appendLoopOnAppenders(event);
    } else {
        return 0;
    }
}

ch.qos.logback.core.spi.AppenderAttachableImpl：

/**
 * Call the <code>doAppend</code> method on all attached appenders.
 */
public int appendLoopOnAppenders(E e) {
    int size = 0;
    // 此数组中保存了我们在Logger[ROOT]配置的两个appender：CONSOLE 和 FILE
    final Appender<E>[] appenderArray = appenderList.asTypedArray();
    final int len = appenderArray.length;
    for (int i = 0; i < len; i++) {
        appenderArray[i].doAppend(e);
        size++;
    }
    return size;
}

我们跟踪到File appender的doAppend方法：
ch.qos.logback.core.UnsynchronizedAppenderBase：

public void doAppend(E eventObject) {
    // WARNING: The guard check MUST be the first statement in the
    // doAppend() method.

    // prevent re-entry.
    if (Boolean.TRUE.equals(guard.get())) {
        return;
    }

    try {
        guard.set(Boolean.TRUE);

        if (!this.started) {
            if (statusRepeatCount++ < ALLOWED_REPEATS) {
                addStatus(new WarnStatus("Attempted to append to non started appender [" + name + "].", this));
            }
            return;
        }

        if (getFilterChainDecision(eventObject) == FilterReply.DENY) {
            return;
        }

        // ok, we now invoke derived class' implementation of append
        this.append(eventObject);

    } catch (Exception e) {
        if (exceptionCount++ < ALLOWED_REPEATS) {
            addError("Appender [" + name + "] failed to append.", e);
        }
    } finally {
        guard.set(Boolean.FALSE);
    }
}

不必关心细枝末节，直接进入this.append(eventObject)方法！

ch.qos.logback.core.OutputStreamAppender：

@Override
protected void append(E eventObject) {
    if (!isStarted()) {
        return;
    }

    subAppend(eventObject);
}

终于来到我们相对熟悉点的类了：
ch.qos.logback.core.rolling.RollingFileAppender：

@Override
protected void subAppend(E event) {
    // The roll-over check must precede actual writing. This is the
    // only correct behavior for time driven triggers.

    // We need to synchronize on triggeringPolicy so that only one rollover
    // occurs at a time
    synchronized (triggeringPolicy) {
    	// 判断是否需要触发滚动日志的操作
        if (triggeringPolicy.isTriggeringEvent(currentlyActiveFile, event)) {
            rollover();
        }
    }

    super.subAppend(event);
}

来到了我们自己配置的滚动策略类（重点关注）：

ch.qos.logback.core.rolling.TimeBasedRollingPolicy：

public boolean isTriggeringEvent(File activeFile, final E event) {
    return timeBasedFileNamingAndTriggeringPolicy.isTriggeringEvent(activeFile, event);
}

为了更好分析下面源码，我们假设现在时间为：2019年10月31日00:00:01，这时日志还未滚动（此时日志目录下有两个文件：stdout.log、stdout.log.2019-10-29.log），然后突然来了10月31日第一条日志打印（即调用了logger.info方法）

ch.qos.logback.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy：

public boolean isTriggeringEvent(File activeFile, final E event) {
    long time = getCurrentTime();	// 获取当前时间戳(ms)，也就是2019年10月31日00:00:01对应的1572451201000
    
    // nextCheck是TimeBasedFileNamingAndTriggeringPolicyBase类的成员变量，表示的是下一次的滚动时间点
    // 此时nextCheck=1572451200000（2019-10-31 00:00:00）
    if (time >= nextCheck) {	// 如果当前时间大于等于该下一次滚动时间点，则执行下面逻辑，此时2019-10-31 00:00:01确实大于2019-10-31 00:00:00，即需要滚动
        Date dateOfElapsedPeriod = dateInCurrentPeriod;	// 上一条日志的时间，我们假设为2019-10-30 23:59:59
        addInfo("Elapsed period: " + dateOfElapsedPeriod);
        // 根据上一条日志时间，算出上一个时间段对应文件名，用于将2019-10-30的stdout.log文件重命名为stdout.log.2019-10-30.log
        elapsedPeriodsFileName = tbrp.fileNamePatternWithoutCompSuffix.convert(dateOfElapsedPeriod);	
        setDateInCurrentPeriod(time);	// 将dateOfElapsedPeriod更新为当前日志时间2019-10-31 00:00:01
        computeNextCheck();	// 计算下次滚动时间点，即将nexCheck更新为2019-11-01 00:00:00
        return true;
    } else {
        return false;
    }
}

此处的nextCheck比较关键，是否需要滚动就看它和当前时间的对比。
该值是由computeNextCheck()方法赋值计算的：

ch.qos.logback.core.rolling.TimeBasedFileNamingAndTriggeringPolicyBase：

protected void computeNextCheck() {
    nextCheck = rc.getNextTriggeringDate(dateInCurrentPeriod).getTime();
}

可以看到该值又是在dateInCurrentPeriod属性基础上计算的。
我们再看start()方法如何初始化这些属性：

可以看到dateInCurrentPeriod取的是stdout.log的最后修改时间！这个非常关键，能防止一些奇怪的错误。

好的，判断完滚动后，就要执行真正的滚动逻辑了：

ch.qos.logback.core.rolling.RollingFileAppender：

// 此方法需要同步，因为它在关闭老文件，然后重新打开新目标文件时需要独占访问
public void rollover() {
    lock.lock();
    try {
    	// 必须确保当前的文件stdout.log已经关闭，因为在windows下无法对已经打开的文件重命名
        this.closeOutputStream();
        attemptRollover();
        attemptOpenFile();
    } finally {
        lock.unlock();
    }
}

下面来分析最关键的attemptRollover() 和 attemptOpenFile()方法：

private void attemptRollover() {
    try {
        rollingPolicy.rollover();
    } catch (RolloverFailure rf) {
        addWarn("RolloverFailure occurred. Deferring roll-over.");
        // we failed to roll-over, let us not truncate and risk data loss
        this.append = true;
    }
}

ch.qos.logback.core.rolling.TimeBasedRollingPolicy：

public void rollover() throws RolloverFailure {

    // when rollover is called the elapsed period's file has
    // been already closed. This is a working assumption of this method.

	// 将上面isTriggeringEvent方法计算得到的elapsedPeriodsFileName赋值到此处，值为：/home/dev/log/xxx/stdout.log.2019-10-30.log
    String elapsedPeriodsFileName = timeBasedFileNamingAndTriggeringPolicy.getElapsedPeriodsFileName();

	// 只取文件名：stdout.log.2019-10-30.log
    String elapsedPeriodStem = FileFilterUtil.afterLastSlash(elapsedPeriodsFileName);

	// 判断是否压缩
    if (compressionMode == CompressionMode.NONE) {
        if (getParentsRawFileProperty() != null) {
        	// 将/home/dev/log/xxx/stdout..log重命名为/home/dev/log/xxx/stdout.log.2019-10-30.log
            renameUtil.rename(getParentsRawFileProperty(), elapsedPeriodsFileName);
        } // else { nothing to do if CompressionMode == NONE and parentsRawFileProperty == null }
    } else {
        if (getParentsRawFileProperty() == null) {
            compressionFuture = compressor.asyncCompress(elapsedPeriodsFileName, elapsedPeriodsFileName, elapsedPeriodStem);
        } else {
            compressionFuture = renameRawAndAsyncCompress(elapsedPeriodsFileName, elapsedPeriodStem);
        }
    }

	// 清理过期日志
    if (archiveRemover != null) {
        Date now = new Date(timeBasedFileNamingAndTriggeringPolicy.getCurrentTime());
        this.cleanUpFuture = archiveRemover.cleanAsynchronously(now);
    }
}

注意的是此处的rename方法底层调用的就是JDK自带File类的renameTo()方法。

此处存在一个坑：

本人在windows（10）、linux（centos7）环境下测试jdk1.8的File-renameTo()方法时，发现执行结果并不相同。

其实之前源码里的注释已经稍微暗示过了：
Renaming under windows does not work for open files.

我的测试结果是：
window :
1.在关闭源文件之前，进行重命名操作，返回 false，重命名失败；
2.目标文件存在时，返回false，重命名失败。

linux:
1.在关闭源文件之前，进行重命名操作，返回 true，重命名成功；
2.目标文件存在时，返回true，覆盖已存在的同名目标文件，重命名成功。

其中第一点的话，源码里已经强调并做过close工作了：make sure to close the hereto active log file! 所以不会有啥问题。

但第二点我测试时就发现问题，因为导致多项目共用日志混乱的直接原因就是rename操作：多次rename滚动日志。

换句话说，我在我本地IDE调试（windows环境）是不会出现这种bug的，因为windows环境的rename很严格！而linux服务器上的项目就悲剧了。

继续看源码：

private void attemptOpenFile() {
    try {
        // 得到当前活跃文件对象，即我们配置文件中指定的\home\dev\log\xxx\stdout.log
        currentlyActiveFile = new File(rollingPolicy.getActiveFileName());	

        // This will also close the file. This is OK since multiple close operations are safe.
        this.openFile(rollingPolicy.getActiveFileName());
    } catch (IOException e) {
        addError("setFile(" + fileName + ", false) call failed.", e);
    }
}

public void openFile(String file_name) throws IOException {
    lock.lock();
    try {
        File file = new File(file_name);
        // 确保stdout.log的父目录已创建
        boolean result = FileUtil.createMissingParentDirectories(file);
        if (!result) {
            addError("Failed to create parent directories for [" + file.getAbsolutePath() + "]");
        }

        ResilientFileOutputStream resilientFos = new ResilientFileOutputStream(file, append, bufferSize.getSize());
        resilientFos.setContext(context);
        setOutputStream(resilientFos);
    } finally {
        lock.unlock();
    }
}

这些方法顾名思义就是openFile而已，rollover方法中执行了重命名操作，那么创建新的stdout.log文件并且open，往里写日志就是这里了！

我们可以发现以上的很多方法中都有线程同步操作，比如lock.lock()、synchronized 等，但是对于我们两个进程级的项目来说，都是徒劳的。所以才会发生各种意料之外的问题，需要特别注意。

至此，源码分析完毕。

---

三、问题产生原因

相信看到这里，大家已经明白问题中的现象是如何发生的了：

我们假设当前时间为：2019-10-30 23:59:59，这时日志目录里只存在活跃打开状态的stdout.log文件，9990和8099端口项目都在往其中写入日志。

然后时间来到了 2019-10-31 00:00:02，这时9990端口项目过来了一条日志打印，我们通过isTriggeringEvent方法进行判断是否需要滚动，结果满足滚动条件（time >= nextCheck），于是将nextCheck属性加1天， stdout.log文件关闭，重命名为stdout.log.2019-10-30.log，再新建stdout.log文件，往其中写入日志。

时间又来到了 2019-10-31 00:00:04，这时8099端口项目过来了一条日志打印，由于nextCheck属性都是存在各自内存中，9990项目在滚动时修改了自己的nextCheck，但是8099不知道，所以判断依旧满足滚动条件，开始滚动！于是将新的stdout.log文件重命名为stdout.log.2019-10-30.log，这时9990已经备份过的老的stdout.log.2019-10-30.log就被8099重命名后新的stdout.log.2019-10-30.log覆盖！然后8099创建属于自己新的stdout.log文件，往其中写入日志。

所以，这就出现了这种奇怪的现象。。

---

四、解决问题（修改源码）

其实的话，一般负载均衡都是多机器多实例，不会放在一台机器上，即使放在一台机器上，其日志也是分开打印，然后再采集汇总、过滤、分析等。我们为了方便强行使其打印在同一个文件中，才出现问题。

不过，每一步的技术变迁都是随着业务发展，随着用户量、数据量的增加而升级，我们也不会担心啥，见招拆招罢了。当然，适当的未雨绸缪也是可行的，前提是对业务发展有相对清晰的认识。

那么，当下的这个问题要如何快速解决呢？我选择尝试修改源码。

大多数开源框架都支持我们继承某个类，重写方法修改属性等，实现我们自定义的功能需求，所谓开闭原则。但是，这得在开源框架开发者的允许范围内才行。

比如我们想实现分钟级别的日志滚动，可以这样：

public class MyTimeBasedFileNamingAndTriggeringPolicy<E> extends DefaultTimeBasedFileNamingAndTriggeringPolicy<E> {
   //这个用来指定时间间隔
   private Integer multiple = 1;

    @Override
    protected void computeNextCheck() {
        nextCheck = rc.getEndOfNextNthPeriod(dateInCurrentPeriod, multiple).getTime();
    }

    public Integer getMultiple() {
        return multiple;
    }

    public void setMultiple(Integer multiple) {
        if (multiple > 1) {
            this.multiple = multiple;
        }
    }
}

然后将我们自定义的MyTimeBasedFileNamingAndTriggeringPolicy类，配置在logback.xml配置文件中，实现自定义扩展修改功能。

我们可以看到只有在某个类的方法或者属性是public或者protected时，我们才允许重写，说明这些属性方法是开发者允许我们扩展的东西。

而我们这里问题所需要修改的逻辑，是不在允许范围里的，所以我们要做的不是简单的扩展，而是对源码进行真正的修改。

修改源码的方式有：

1.直接将修改后的源码编译成class文件，替换jar包里的对应class文件，再运行即可

2.下载整个源码，修改后，将其打包上传到私服，在项目中使用私服地址引入即可

3.在自己代码的根目录中添加与开源框架包路径相同的类，这也是我暂时选择的简单方法，具体操作如下：

我要修改ch.qos.logback.core.rolling.TimeBasedRollingPolicy类，于是我在项目目录src.main.java下创建与com目录同级的ch.qos.logback.core.rolling.TimeBasedRollingPolicy类，自己就可以随意修改了。

2020年4月24号补充：

有小伙伴私信我此处可能存在一点疑问，我详细说明下：

首先上面讲的修改源码的第三种方法（添加包路径相同的同名类），原理是利用了类加载顺序，jvm类加载是先依赖了jdk自带类、再就是我们项目本身写的类、最后是maven依赖的第三方类库。所以这个方法其实就是将原本maven第三方logback类库中的TimeBasedRollingPolicy类 由 我们代码里面自己编写的同路径类TimeBasedRollingPolicy类进行覆盖，因为jvm只要发现已经加载过的类，再此碰到同名类就会忽略掉，也就是我们根据类加载顺序成功覆盖了加载最晚的三方logback类。

所以我的具体操作是：
先如下图建立与logback源码里面的TimeBasedRollingPolicy类相同包路径，再将该类复制到自定义包路径下面。
注意：我是直接原封不动复制过去的，并不是新建一个TimeBasedRollingPolicy类再孤零零实现rollover()方法，因为rollover()方法里面需要很多外部属性，直接实现是获取不到这些属性的！

修改后的 rollover()方法：

public void rollover() throws RolloverFailure {

    // when rollover is called the elapsed period's file has
    // been already closed. This is a working assumption of this method.

    String elapsedPeriodsFileName = timeBasedFileNamingAndTriggeringPolicy.getElapsedPeriodsFileName();

    String elapsedPeriodStem = FileFilterUtil.afterLastSlash(elapsedPeriodsFileName);

    if (compressionMode == CompressionMode.NONE) {
        /**
         * ========================================================================================
         * 源码修改处：如果已存在目标文件则不用重命名
         * ========================================================================================
         */

        if (getParentsRawFileProperty() != null && !new File(elapsedPeriodsFileName).exists()) {
            renameUtil.rename(getParentsRawFileProperty(), elapsedPeriodsFileName);
        } // else { nothing to do if CompressionMode == NONE and parentsRawFileProperty == null }

    } else {
        if (getParentsRawFileProperty() == null) {
            compressionFuture = compressor.asyncCompress(elapsedPeriodsFileName, elapsedPeriodsFileName, elapsedPeriodStem);
        } else {
            compressionFuture = renameRawAndAsyncCompress(elapsedPeriodsFileName, elapsedPeriodStem);
        }
    }

    if (archiveRemover != null) {
        Date now = new Date(timeBasedFileNamingAndTriggeringPolicy.getCurrentTime());
        this.cleanUpFuture = archiveRemover.cleanAsynchronously(now);
    }
}

如上所示，我只是简单的在重命名之前增加一步判断：如果已经存在需要重命名的目标文件，就放弃重命名操作。

经过测试，暂时没啥问题了。。以后有问题再说吧，夜深了。。

---