聊一下 Java 的日志系列三

上周因为一些事情没有更新在这里，是因为新电脑还没到，手头没有把移动硬盘里的 time machine 恢复出来的机器，所以单独更了一篇在新建的一个 cloudflare page 服务上，总体体验还可以，就是有个小点后面可以讲一下，继续完善下 Java 的这个日志，或者说主要讲的是 logback
前面讲了logback 的初始化逻辑，后面就是我最开始来看这个的逻辑，日志的滚动策略的触发逻辑
我们常规的记录日志的方式比如

logger.info("log some thing and biz info: {}",biz);

这里就调用了
ch.qos.logback.classic.Logger#info(java.lang.String, java.lang.Object)

public void info(String format, Object arg) {
    filterAndLog_1(FQCN, null, Level.INFO, format, arg, null);
}

这里的 FQCN 就是这个类的全限定名

public static final String FQCN = ch.qos.logback.classic.Logger.class.getName();

这个具体的 filterAndLog_1 方法还是在同一个 Logger 类里的
ch.qos.logback.classic.Logger#filterAndLog_1

private void filterAndLog_1(final String localFQCN, final Marker marker, final Level level, final String msg, final Object param, final Throwable t) {

final FilterReply decision = loggerContext.getTurboFilterChainDecision_1(marker, this, level, msg, param, t);

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

buildLoggingEventAndAppend(localFQCN, marker, level, msg, new Object[] { param }, t);
}

这里面先是走过滤器逻辑，如果是拒绝的，那就不往下执行，也就不执行下面的写日志逻辑了，如果是中性的，那就判断日志级别是否符合，如果直接是拒绝就 return 了，如果是 ACCEPT 就往下执行了

public enum FilterReply {
    DENY, NEUTRAL, ACCEPT;
}

然后继续调用同样的类的方法
ch.qos.logback.classic.Logger#buildLoggingEventAndAppend

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);
}

先把日志包装成 LoggingEvent ，然后调用
ch.qos.logback.classic.Logger#callAppenders

public void callAppenders(ILoggingEvent event) {
    int writes = 0;
    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);
    }
}

这里会按 Logger 调用 appendLoopOnAppenders

private int appendLoopOnAppenders(ILoggingEvent event) {
    if (aai != null) {
        return aai.appendLoopOnAppenders(event);
    } else {
        return 0;
    }

继续调用事件的
ch.qos.logback.core.spi.AppenderAttachableImpl#appendLoopOnAppenders

public int appendLoopOnAppenders(E e) {
    int size = 0;
    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;
}

因为 Logger 里有关联 appender，就具体调用关联的 appender 来添加日志
然后就接着调用
ch.qos.logback.core.UnsynchronizedAppenderBase#doAppend 方法

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);
        }
    }

这里先判断了 guard 的状态，guard 是个 ThreadLocal，是为了拦截异常的无限循环调用，这里有些疑惑的，看了一圈可能相关的是前面的 Logger 会往父级查找，然后如果不同层级的 Logger 关联了相同的 appender 的话，或者这个 doAppend 又被其他 appender 调用了，就可能会出现循环调用，然后会在开始实际的 append的之前先设置 guard 状态，
然后再执行 append，这里会走到
ch.qos.logback.core.OutputStreamAppender#append

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

subAppend(eventObject);
}

忘了补充下，我们这里使用的是
ch.qos.logback.core.rolling.RollingFileAppender
接下去就是调用的 RollingFileAppender 的 subAppend 方法

@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);
}

这里就会先判断是否触发事件，
而这里就是主要的逻辑，看是否需要走 rollover，也就是具体的滚动逻辑

@Override
    public boolean isTriggeringEvent(File activeFile, final E event) {

long time = getCurrentTime();

// first check for roll-over based on time
        if (time >= nextCheck) {
            Date dateInElapsedPeriod = dateInCurrentPeriod;
            elapsedPeriodsFileName = tbrp.fileNamePatternWithoutCompSuffix.convertMultipleArguments(dateInElapsedPeriod, currentPeriodsCounter);
            currentPeriodsCounter = 0;
            setDateInCurrentPeriod(time);
            computeNextCheck();
            return true;
        }

// next check for roll-over based on size
        if (invocationGate.isTooSoon(time)) {
            return false;
        }

if (activeFile == null) {
            addWarn("activeFile == null");
            return false;
        }
        if (maxFileSize == null) {
            addWarn("maxFileSize = null");
            return false;
        }
        if (activeFile.length() >= maxFileSize.getSize()) {

elapsedPeriodsFileName = tbrp.fileNamePatternWithoutCompSuffix.convertMultipleArguments(dateInCurrentPeriod, currentPeriodsCounter);
            currentPeriodsCounter++;
            return true;
        }

return false;
    }

这里主要就用到了 nextCheck 判断，如果通过判断就可以执行滚动了，然后就是后面的判断，是否太快了，也就是 isTooSoon 然后再看当前的活跃日志以及最大文件大小是否设置，然后如果当前的活跃日志的大小超过了配置也会触发滚动

</div