聊一下 Java 的日志系列三

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

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

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

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

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

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

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

1
2
3
4
5
6
7
8
9
10
11
12
13
14
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 就往下执行了

1
2
3
public enum FilterReply {
DENY, NEUTRAL, ACCEPT;
}

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

1
2
3
4
5
6
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

1
2
3
4
5
6
7
8
9
10
11
12
13
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

1
2
3
4
5
6
private int appendLoopOnAppenders(ILoggingEvent event) {
if (aai != null) {
return aai.appendLoopOnAppenders(event);
} else {
return 0;
}

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

1
2
3
4
5
6
7
8
9
10
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 方法

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
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

1
2
3
4
5
6
7
8
@Override
protected void append(E eventObject) {
if (!isStarted()) {
return;
}

subAppend(eventObject);
}

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

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
@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,也就是具体的滚动逻辑

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
@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 然后再看当前的活跃日志以及最大文件大小是否设置,然后如果当前的活跃日志的大小超过了配置也会触发滚动