在Logback(2) 基本配置文章中的【配置 root logger】小节中我们碰到了一个日志打印两次的问题,这里我们可以简单看一下源码理解一下日志打印的大致流程:
我们从这个方法开始
LOGGER.info("Did it again!");
我们从接口找到logback的实现类:
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) {
// step1
final FilterReply decision = loggerContext.getTurboFilterChainDecision_0_3OrMore(marker, this, level, msg, params, t);
// step2
if (decision == FilterReply.NEUTRAL) {
if (effectiveLevelInt > level.levelInt) {
return;
}
} else if (decision == FilterReply.DENY) {
return;
}
//step3
buildLoggingEventAndAppend(localFQCN, marker, level, msg, params, t);
}
这里面有三个步骤:
- 执行TurboFilter的处理逻辑
- 根据TurboFilter返回的结果和Level信息做判断,如果不需要写日志则直接退出
- 需要写日志了,调用buildLoggingEventAndAppend()方法来构建日志并写入。
TurboFilter我们后续讲到这个配置项再谈,看一下步骤二,我们大致能够知道这段代码是用来检查当前logger配置的日志等级和传入的日志请求指定的日志等级,以决定是否需要打印这条日志
注意:这里就是判断日志打不打印了,所以这里就解释了上文中通过父级的appender输出日志为啥和父级的logger等级无关,因为这里是在判断当前日志是否需要输出了,而appender的调用是在下文中执行的,我们可以继续往下看
假如我们的日志等级满足打印的条件,则执行:
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);
}
buildLoggingEventAndAppend
方法构建了LoggingEvent
对象,当然这个对象目前对我们来说不是那么需要关心的,我们关注后面调用的callAppenders(le);
方法,顾名思义这里在调用appender来处理打印日志事宜了。
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);
}
}
callAppenders()
方法中我们先看这段循环
for (Logger l = this; l != null; l = l.parent)
this指向当前的logger,我们这里先只要知道,l.parent
会指向它的父级logger,例如我们的TestAppender类是在com.exercise.newpac
包下,当前的logger的name是com.exercise.newpac.TestAppender
,它的parent是`com.exercise.newpac
,虽然我们在配置文件里没有配置这个logger,但是他还是生成一个logger对象不断向上遍历,每一次循环都会调用appendLoopOnAppenders
,直到ROOT logger为止。所以这里我们从代码层面上解释通了为什么多个appender会导致日志打印两次的问题。
继续看appendLoopOnAppenders()
方法:
transient private AppenderAttachableImpl<ILoggingEvent> aai;
private int appendLoopOnAppenders(ILoggingEvent event) {
if (aai != null) {
return aai.appendLoopOnAppenders(event);
} else {
return 0;
}
}
这里涉及到AppenderAttachableImpl
类的实例aai,这个AppenderAttachableImpl
类也挺复杂的,涉及到并发和线程安全。我们先跳过它的细节,将它简化为一个logger中配置的appender list,这样看aai.appendLoopOnAppenders()
方法中的代码就简单了:
public int appendLoopOnAppenders(E e) {
int size = 0;
for (Appender<E> appender : appenderList) {
appender.doAppend(e);
size++;
}
return size;
}
每次appendLoopOnAppenders()
方法(非aai的)将被调用,这个方法会返回其调用并使用过的appender的个数,方法callAppenders
中的writes变量会统计总数。遍历结束后,会检查writes统计的结果,如果为0表明整个过程中都没有任何appender被使用,则会打印警告:
final void noAppenderDefinedWarning(final Logger logger) {
if (noAppenderWarning++ == 0) {
getStatusManager().add(
new WarnStatus("No appenders present in context [" + getName()
+ "] for logger [" + logger.getName() + "].", logger));
}
}
所以平时如果看到这个警告,就要注意检查对应logger的appender设置了。