聊一下 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
3public 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
14private 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
3public enum FilterReply {
DENY, NEUTRAL, ACCEPT;
}
然后继续调用同样的类的方法ch.qos.logback.classic.Logger#buildLoggingEventAndAppend
1
2
3
4
5
6private 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
13public 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
6private 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
10public 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
34public 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
protected void append(E eventObject) {
if (!isStarted()) {
return;
}
subAppend(eventObject);
}
忘了补充下,我们这里使用的是ch.qos.logback.core.rolling.RollingFileAppender
接下去就是调用的 RollingFileAppender
的 subAppend
方法1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
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
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 然后再看当前的活跃日志以及最大文件大小是否设置,然后如果当前的活跃日志的大小超过了配置也会触发滚动