记一次蛋疼的logback之旅
前言
我们现在打印日志其实基本都是用的slf4j。大家都知道它是一个公共的门面，背后你可以用具体的日志实现，例如log4j，log4j2，logback。slf4j本身naive的实现就是logback，现在市面上大部分也是用的它。昨天打印日志的时候看到这一句话:
logger.info("The result is {}", result);
当时我就在想，我记得这里最终会调用result.toString()填充到{}中并最终完成打印。但我们难免会有这样的需求，如果一个对象没有重写自己的toString方法（比方说忘记了，或者更绝望的，对象来源于第三方jar），亦或是这个对象的toString方法显示的内容并不满足我们日志的需求（比方说脱敏），我们该怎么做呢？直觉上我认为日志框架层应该会有相应的扩展点来做这个事，因此我就开始了一次蛋疼的logback之旅。
文档の初体验
我想到的第一件事情是去看看logback的文档，不得不说logback的文档还是很到位了，把我以前都不太确定和清楚地点都讲到了，并且还有类似这种序列图来说明写日志的过程。
从这图上面有一个类自然而然的引起了我的注意。
ch.qos.logback.core.layout
这个类doLayout方法返回了一个String，我们就来看看这里能不能解决。文档里面有这句话：
Layouts are logback components responsible for transforming an incoming event into a String. The
format()method in theLayoutinterface takes an object that represents an event (of any type) and returns a String.
简而言之，每个需要打印的日志请求到最后都会被封装到一个实现ILoggingEvent接口的事件中，然后Layout就负责将这个事件通过format方法转换成一个字符串打印出来。看上去似乎有戏，但是在查阅了整个文档之后发现，我们需要的信息实际上都封装在这里：
相当于在 Layout输出之前，我们应用所打出来的信息都已经作为一整个 message字符串关联到了我们的日志事件中， Layout仅仅是把这个已经处理好的字符串按照自己的格式输出而已。所以我们应该在 Layout介入之前完成我们参数的转换。
代码の初体验
文档不行，就来看代码吧。稍微跟一下代码，结果是令人窒息的（没有down下来source，不过不影响，过程有点枯燥，没兴趣的读者可以直接到结论）。
追溯路线
当logger.info发生时：
// in ch.qos.logback.classic.Logger.class
public void info(String format, Object arg) {
this.filterAndLog_1(FQCN, (Marker)null, Level.INFO, format, arg, (Throwable)null);
}
private void filterAndLog_1(String localFQCN, Marker marker, Level level, String msg, Object param, Throwable t) {
FilterReply decision = this.loggerContext.getTurboFilterChainDecision_1(marker, this, level, msg, param, t);
if (decision == FilterReply.NEUTRAL) {
if (this.effectiveLevelInt > level.levelInt) {
return;
}
} else if (decision == FilterReply.DENY) {
return;
}
this.buildLoggingEventAndAppend(localFQCN, marker, level, msg, new Object[]{param}, t);
}
private void buildLoggingEventAndAppend(String localFQCN, Marker marker, Level level, String msg, Object[] params, Throwable t) {
LoggingEvent le = new LoggingEvent(localFQCN, this, level, msg, t, params);
le.setMarker(marker);
this.callAppenders(le);
}
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;
}
}
if (writes == 0) {
this.loggerContext.noAppenderDefinedWarning(this);
}
}
private int appendLoopOnAppenders(ILoggingEvent event) {
return this.aai != null ? this.aai.appendLoopOnAppenders(event) : 0;
}
第一段很简单，做了一堆逻辑判断之后把日志请求封装成了一个ILoggingEvent事件，然后传递给appender
// in ch.qos.logback.core.spi.AppenderAttachableImpl.class
public int appendLoopOnAppenders(E e) {
int size = 0;
Appender<E>[] appenderArray = (Appender[])this.appenderList.asTypedArray();
int len = appenderArray.length;
for(int i = 0; i < len; ++i) {
appenderArray[i].doAppend(e);
++size;
}
return size;
}
这里就是一个bridge，也没啥可说的
// in ch.qos.logback.core.UnsynchronizedAppenderBase.class
public void doAppend(E eventObject) {
if (!Boolean.TRUE.equals(this.guard.get())) {
try {
this.guard.set(Boolean.TRUE);
if (this.started) {
if (this.getFilterChainDecision(eventObject) == FilterReply.DENY) {
return;
}
this.append(eventObject);
return;
}
if (this.statusRepeatCount++ < 3) {
this.addStatus(new WarnStatus("Attempted to append to non started appender [" + this.name + "].", this));
}
} catch (Exception var6) {
if (this.exceptionCount++ < 3) {
this.addError("Appender [" + this.name + "] failed to append.", var6);
}
return;
} finally {
this.guard.set(Boolean.FALSE);
}
}
}
// in ch.qos.logback.core.OutputStreamAppender.class
protected void append(E eventObject) {
if (this.isStarted()) {
this.subAppend(eventObject);
}
}
protected void subAppend(E event) {
if (this.isStarted()) {
try {
if (event instanceof DeferredProcessingAware) {
((DeferredProcessingAware)event).prepareForDeferredProcessing();
}
byte[] byteArray = this.encoder.encode(event);
this.writeBytes(byteArray);
} catch (IOException var3) {
this.started = false;
this.addStatus(new ErrorStatus("IO failure in appender", this, var3));
}
}
}
这里以ConsoleAppender为整个继承线路来考察，我们看到这里也是首先做了内部的责任链看时候需要打印，如果需要的话就调用append方法。到了最后的subAppend方法我们看到调用了encoder来得到我们需要打印的字节数组，而encoder其实就是调用了底层的layout。按照我们之前的推论，唯一的变化可能就来自于：
((DeferredProcessingAware)event).prepareForDeferredProcessing();
我们再跟进去看看：
// in ch.qos.logback.classic.spi.LoggingEvent
public void prepareForDeferredProcessing() {
this.getFormattedMessage();
this.getThreadName();
this.getMDCPropertyMap();
}
public String getFormattedMessage() {
if (this.formattedMessage != null) {
return this.formattedMessage;
} else {
if (this.argumentArray != null) {
this.formattedMessage = MessageFormatter.arrayFormat(this.message, this.argumentArray).getMessage();
} else {
this.formattedMessage = this.message;
}
return this.formattedMessage;
}
}
public String getFormattedMessage() {
if (this.formattedMessage != null) {
return this.formattedMessage;
} else {
if (this.argumentArray != null) {
this.formattedMessage = MessageFormatter.arrayFormat(this.message, this.argumentArray).getMessage();
} else {
this.formattedMessage = this.message;
}
return this.formattedMessage;
}
}
这里我们跟到了一个MessageFormatter类，这个类是LoggingEvent硬编码调用的静态方法，我们再跟进去（已经有点不祥的预感）:
// in org.slf4j.helpers.MessageFormatter
public static final FormattingTuple arrayFormat(String messagePattern, Object[] argArray) {
Throwable throwableCandidate = getThrowableCandidate(argArray);
Object[] args = argArray;
if (throwableCandidate != null) {
args = trimmedCopy(argArray);
}
return arrayFormat(messagePattern, args, throwableCandidate);
}
public static final FormattingTuple arrayFormat(String messagePattern, Object[] argArray, Throwable throwable) {
if (messagePattern == null) {
return new FormattingTuple((String)null, argArray, throwable);
} else if (argArray == null) {
return new FormattingTuple(messagePattern);
} else {
int i = 0;
StringBuilder sbuf = new StringBuilder(messagePattern.length() + 50);
for(int L = 0; L < argArray.length; ++L) {
int j = messagePattern.indexOf("{}", i);
if (j == -1) {
if (i == 0) {
return new FormattingTuple(messagePattern, argArray, throwable);
}
sbuf.append(messagePattern, i, messagePattern.length());
return new FormattingTuple(sbuf.toString(), argArray, throwable);
}
if (isEscapedDelimeter(messagePattern, j)) {
if (!isDoubleEscaped(messagePattern, j)) {
--L;
sbuf.append(messagePattern, i, j - 1);
sbuf.append('{');
i = j + 1;
} else {
sbuf.append(messagePattern, i, j - 1);
deeplyAppendParameter(sbuf, argArray[L], new HashMap());
i = j + 2;
}
} else {
sbuf.append(messagePattern, i, j);
deeplyAppendParameter(sbuf, argArray[L], new HashMap());
i = j + 2;
}
}
sbuf.append(messagePattern, i, messagePattern.length());
return new FormattingTuple(sbuf.toString(), argArray, throwable);
}
}
private static void deeplyAppendParameter(StringBuilder sbuf, Object o, Map<Object[], Object> seenMap) {
if (o == null) {
sbuf.append("null");
} else {
if (!o.getClass().isArray()) {
safeObjectAppend(sbuf, o);
} else if (o instanceof boolean[]) {
booleanArrayAppend(sbuf, (boolean[])((boolean[])o));
} else if (o instanceof byte[]) {
byteArrayAppend(sbuf, (byte[])((byte[])o));
} else if (o instanceof char[]) {
charArrayAppend(sbuf, (char[])((char[])o));
} else if (o instanceof short[]) {
shortArrayAppend(sbuf, (short[])((short[])o));
} else if (o instanceof int[]) {
intArrayAppend(sbuf, (int[])((int[])o));
} else if (o instanceof long[]) {
longArrayAppend(sbuf, (long[])((long[])o));
} else if (o instanceof float[]) {
floatArrayAppend(sbuf, (float[])((float[])o));
} else if (o instanceof double[]) {
doubleArrayAppend(sbuf, (double[])((double[])o));
} else {
objectArrayAppend(sbuf, (Object[])((Object[])o), seenMap);
}
}
}
private static void safeObjectAppend(StringBuilder sbuf, Object o) {
try {
String oAsString = o.toString();
sbuf.append(oAsString);
} catch (Throwable var3) {
Util.report("SLF4J: Failed toString() invocation on an object of type [" + o.getClass().getName() + "]", var3);
sbuf.append("[FAILED toString()]");
}
}
更到最后，我们看到就直接调用了toString，并没有任何扩展点可以让我们来搞定我们的定制化输出参数的需求。难道就没有其他路子了么？当然也不是，我们可以看到在输出日志之前，全局和Appender本身都会调用一个责任链来判断这个日志请求是否需要打印出来，使用到的ILoggingEvent我们看到是包含了一个类型为Object[]的params变量代表日志输出的参数。好吧，既然类型是对象的数组，那我们自己写一个Filter来转换我们的参数，输出成json字符串，在设置回去，是不是就可以了？
代码结论
logback用硬编码的方式调用了参数的toString方法，没有扩展点可以使用，但是可以通过扩展Appender甚至是全局的过滤Filter来转换参数。
验证
我们首先写一个Filter：
public class CustomerFilter extends Filter<ILoggingEvent> {
@Override
public FilterReply decide(ILoggingEvent event) {
if(event.getLoggerName().startsWith("com.roger")){
Object[] params = event.getArgumentArray();
for(int index = 0; index < params.length; index++){
Object param = params[index];
if(!param.getClass().isPrimitive() && param instanceof Serializable){
params[index] = JSON.toJSONString(param);
}
}
}
return FilterReply.ACCEPT;
}
}
然后再准备一个logback.xml，这里直接让我们的logger继承使用了root的Appender，实际应用可以自行配置：
<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="false">
<!--定义日志文件的存储地址 勿在 LogBack 的配置中使用相对路径-->
<property name="LOG_HOME" value="/test/log" />
<!-- 控制台输出 -->
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<filter class="com.roger.dblock.logger.CustomerFilter"/>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符-->
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern>
</encoder>
</appender>
<logger name="com.roger.dblock.controller.TokenController" level="INFO"/>
<!-- 日志输出级别 -->
<root level="INFO">
<appender-ref ref="STDOUT" />
</root>
</configuration>
然后在我们的代码中加一句打印日志：
@GetMapping("test")
public String test() {
Token result = new Token();
result.setToken("123");
result.setAppId("321");
logger.info("yes: {}", result);
return "yes";
}
注意这里这个Token类并没有实现toString方法，然后我们启动打印日志试试：
2019-01-22 17:23:32.928 [http-nio-8090-exec-7] INFO com.roger.dblock.controller.TokenController - yes: {"appId":"321","token":"123"}
这个看到，我们通过自定义Filter将我们的参数定制化打印出来了，后续还可以结合注解来做自定义格式、脱敏等等。
结论
这篇文章非常蛋疼的过了一遍logback的各个组件以及打印日志的过程，并且通过扩展Filter来完成了日志框架层面的参数自定义输出。但是我个人是不太喜欢这样的操作方式，因为Filter语义上讲应该只是完成日志请求的过滤，如果自己还要做参数转换会给开发人员带来不透明性。但对于我的这个需求可能暂时也没找到更好的方式，当然也欢迎大家向我扔鸡蛋。