记一次蛋疼的logback之旅

Posted 桃桃爹的书桌

tags:

篇首语:本文由小常识网(cha138.com)小编为大家整理,主要介绍了记一次蛋疼的logback之旅相关的知识,希望对你有一定的参考价值。

前言

我们现在打印日志其实基本都是用的slf4j。大家都知道它是一个公共的门面,背后你可以用具体的日志实现,例如log4j,log4j2,logback。slf4j本身naive的实现就是logback,现在市面上大部分也是用的它。昨天打印日志的时候看到这一句话:

logger.info("The result is {}", result);

当时我就在想,我记得这里最终会调用result.toString()填充到{}中并最终完成打印。但我们难免会有这样的需求,如果一个对象没有重写自己的toString方法(比方说忘记了,或者更绝望的,对象来源于第三方jar),亦或是这个对象的toString方法显示的内容并不满足我们日志的需求(比方说脱敏),我们该怎么做呢?直觉上我认为日志框架层应该会有相应的扩展点来做这个事,因此我就开始了一次蛋疼的logback之旅。

文档の初体验

我想到的第一件事情是去看看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 the Layout interface takes an object that represents an event (of any type) and returns a String.

简而言之,每个需要打印的日志请求到最后都会被封装到一个实现ILoggingEvent接口的事件中,然后Layout就负责将这个事件通过format方法转换成一个字符串打印出来。看上去似乎有戏,但是在查阅了整个文档之后发现,我们需要的信息实际上都封装在这里:

message

相当于在 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语义上讲应该只是完成日志请求的过滤,如果自己还要做参数转换会给开发人员带来不透明性。但对于我的这个需求可能暂时也没找到更好的方式,当然也欢迎大家向我扔鸡蛋。


以上是关于记一次蛋疼的logback之旅的主要内容,如果未能解决你的问题,请参考以下文章

蛋疼的mysql之旅:事务事务的特性事务的隔离级别

一个令人蛋疼的NDK链接错误

如何把php项目部署到阿里云服务器window server2012__含公网ip访问时jquery/ajax失效解决办法

python蛋疼的编码decodeencodeunicodestrbyte的问题都在这了

Java学习笔记——山西煤老板蛋疼的拉车问题

python中令人蛋疼的地方及一些技巧