log.error()底层到底做了些啥？

太过爱你忘了你带给我的痛 2023-07-15 11:21 202阅读 0赞

今天给大家介绍一下logback日志，底层是如何实现的。这边我们打印一下error级别的日志，看看从log.error到输出磁盘，这个过程中到底发生了些什么，并从源码级别揭秘整个日常的输出过程。

我们先在代码中编写log.error，作为日志入口。

log.error("测试日志输出：accountId:{},site:{}", accountId, site);

进入error()函数中，我们可以看到，在打印日志之前，第一件事情是判断该log日志是否可以输出。（比如你配置文件配置的是error级别，你输出的却是info级别的日志，那就会直接被return掉，日志也不会输出到控制台或者文件中）

@Override
        public void logIfEnabled(final String fqcn, final Level level, final Marker marker, final String message,
                final Object p0, final Object p1) {
            if (isEnabled(level, marker, message, p0, p1)) {
                logMessage(fqcn, level, marker, message, p0, p1);
            }
        }

在logIfEnabled函数中会进行日志是否可输出判断，我们接下来看看logIfEnabled函数中做了哪些事情。

private boolean isEnabledFor(final Level level, final Marker marker) {
            final org.slf4j.Marker slf4jMarker = getMarker(marker);
            switch (level.getStandardLevel()) {
                case DEBUG :
                    return logger.isDebugEnabled(slf4jMarker);
                case TRACE :
                    return logger.isTraceEnabled(slf4jMarker);
                case INFO :
                    return logger.isInfoEnabled(slf4jMarker);
                case WARN :
                    return logger.isWarnEnabled(slf4jMarker);
                case ERROR :
                    return logger.isErrorEnabled(slf4jMarker);
                default :
                    return logger.isErrorEnabled(slf4jMarker);
    
            }
        }

logIfEnabled函数一直往里面调用，最后我们可以看到如上一段代码，这段代码主要将不同级别的日志分别调用不用的日志是否可打印判断方法，我们这边的日志级别的error，所以我们直接看isErrorEnabled函数中的实现。

public boolean isErrorEnabled(Marker marker) {
            FilterReply decision = callTurboFilters(marker, Level.ERROR);
            if (decision == FilterReply.NEUTRAL) {
                return effectiveLevelInt <= Level.ERROR_INT;
            } else if (decision == FilterReply.DENY) {
                return false;
            } else if (decision == FilterReply.ACCEPT) {
                return true;
            } else {
                throw new IllegalStateException("Unknown FilterReply value: " + decision);
            }
        }

在isErrorEnabled函数中主要做了两件事情，一个是通过callTurboFilters函数获取当前日志FilterReply ，然后和配置文件配置日志等级Level.ERROR\_INT进行判断，最后返回boolean结果。

**callTurboFilters函数：**

callTurboFilters函数主要是用来过滤配置文件中特殊的配置，如果没有特殊配置则直接返回FilterReply.NEUTRAL（正常）。

**effectiveLevelInt：**

现在问题关键就是effectiveLevelInt的值是从哪里赋值的，因为Level.ERROR\_INT的值是固定4000

public static final int ERROR_INT = 40000;

这边effectiveLevelInt的初始值，是在容器启动的时候赋值的，具体值和logback配置文件有关。因为spring容器启动的时候会设置每一个级别的effectiveLevelInt值，初始值分为trace、debug、info、warn、error、日志关闭等几个值。

![image][]

这边因为我配置的日志级别是异步error（何为异步，稍后再解释），所以isErrorEnabled方法返回的是ture。

<appender-ref ref="file_error_async"/>

logIfEnabled函数就介绍到这边了，下面就是日志打印的模块了，日志打印的起始函数是logMessage函数，我们来看看logMessage函数中又做了哪些事情。

protected void logMessage(final String fqcn, final Level level, final Marker marker, final String message,
                final Object p0, final Object p1) {
            final Message msg = messageFactory.newMessage(message, p0, p1);
            logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
        }

logMessage函数中对日志打印内容和参数做了处理，并封装为Message对象，Message对象中比较重要的三个字段就是messagePattern、parameters、locale。一个是需要打印的日志、一个是\{\}中参数、最后一个就是每一个参数在messagePattern对应的参数下标。如下图所示：

![image][image 1]

logMessageSafely函数一直往下走，会进入logMessage函数，代码如下所示：

@Override
        public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message, final Throwable t) {
            if (locationAwareLogger != null) {
                if (message instanceof LoggerNameAwareMessage) {
                    ((LoggerNameAwareMessage) message).setLoggerName(getName());
                }
                locationAwareLogger.log(getMarker(marker), fqcn, convertLevel(level), message.getFormattedMessage(),
                        message.getParameters(), t);
            } else {
                switch (level.getStandardLevel()) {
                    case DEBUG :
                        logger.debug(getMarker(marker), message.getFormattedMessage(), message.getParameters(), t);
                        break;
                    case TRACE :
                        logger.trace(getMarker(marker), message.getFormattedMessage(), message.getParameters(), t);
                        break;
                    case INFO :
                        logger.info(getMarker(marker), message.getFormattedMessage(), message.getParameters(), t);
                        break;
                    case WARN :
                        logger.warn(getMarker(marker), message.getFormattedMessage(), message.getParameters(), t);
                        break;
                    case ERROR :
                        logger.error(getMarker(marker), message.getFormattedMessage(), message.getParameters(), t);
                        break;
                    default :
                        logger.error(getMarker(marker), message.getFormattedMessage(), message.getParameters(), t);
                        break;
                }
            }
        }

logMessage函数中最核心的就是locationAwareLogger.log函数了，其中message.getFormattedMessage()函数是用来将日志中\{\}和参数对应上，返回我们要打印的日志String，我们先来看看message.getFormattedMessage()函数里面做了些啥。

locationAwareLogger.log(getMarker(marker), fqcn, convertLevel(level), message.getFormattedMessage(),message.getParameters(), t);

getFormattedMessage函数主要是创建一个StringBuilder对象，然后对日志字符串进行处理，最后返回要打印的字符串。

/**
         * Returns the formatted message.
         * @return the formatted message.
         */
        @Override
        public String getFormattedMessage() {
            if (formattedMessage == null) {
                final StringBuilder buffer = getThreadLocalStringBuilder();
                formatTo(buffer);
                formattedMessage = buffer.toString();
                StringBuilders.trimToMaxSize(buffer, Constants.MAX_REUSABLE_MESSAGE_SIZE);
            }
            return formattedMessage;
        }

formatTo函数主要是根据日志输出的类型，选择对应的日志处理方式。我们的日志类型会通过ParameterFormatter.formatMessage2函数进行日志处理。

@Override
        public void formatTo(final StringBuilder buffer) {
            if (formattedMessage != null) {
                buffer.append(formattedMessage);
            } else {
                if (indices[0] < 0) {
                    ParameterFormatter.formatMessage(buffer, messagePattern, argArray, usedCount);
                } else {
                    ParameterFormatter.formatMessage2(buffer, messagePattern, argArray, usedCount, indices);
                }
            }
        }

formatMessage2函数主要是通过StringBuilder的append方法，对日志中\{\}和参数进行拼接，最后返回拼接好的日志字符串。

/**
         * Replace placeholders in the given messagePattern with arguments.
         *
         * @param buffer the buffer to write the formatted message into
         * @param messagePattern the message pattern containing placeholders.
         * @param arguments      the arguments to be used to replace placeholders.
         */
        static void formatMessage2(final StringBuilder buffer, final String messagePattern,
                final Object[] arguments, final int argCount, final int[] indices) {
            if (messagePattern == null || arguments == null || argCount == 0) {
                buffer.append(messagePattern);
                return;
            }
            int previous = 0;
            for (int i = 0; i < argCount; i++) {
                buffer.append(messagePattern, previous, indices[i]);
                previous = indices[i] + 2;
                recursiveDeepToString(arguments[i], buffer, null);
            }
            buffer.append(messagePattern, previous, messagePattern.length());
        }

要打印的日志有了，接下来就是将日志输出到我们配置的文件中或者打印到控制台上面。日志的打印有两种模式，一种是异步的、一种是同步的，我们先来看一下异步的日志输出到底是怎么实现的。

从locationAwareLogger.log函数中一直往下走，我们可以看到callAppenders函数，这个函数的作用就是启动线程来打印日志。我们进入callAppenders中看看里面到底是在干嘛。

/**
         * Invoke all the appenders of this logger.
         * 
         * @param event
         *          The event to log
         */
        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的parent节点，一直循环到父节点为null的时候，会进入aai.appendLoopOnAppenders(event)函数中，此函数就是将所有级别的日志全部输出指定位置，我们来具体看一下它的实现。

/**
     * Call the <code>doAppend</code> method on all attached appenders.
    */
    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;
        }

appenderArray数组中保存着我们log配置文件中所有的输出配置，如下图所示：

![image][image 2]

appenderArray\[i\].doAppend(e)中的doAppend就是针对每一种打印类型进行日志打印。我们进入doAppend函数看看里面具体做了哪些事情。

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);
            }
        }

里面进行了一系列的判断，最后会进入this.append(eventObject)中，我们接着跟踪后续的代码。

@Override
        protected void append(E eventObject) {
            if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) {
                return;
            }
            preprocess(eventObject);
            put(eventObject);
        }

我们再进入put函数中看看最后打印的真相是啥。

private void put(E eventObject) {
            if (neverBlock) {
                blockingQueue.offer(eventObject);
            } else {
                putUninterruptibly(eventObject);
            }
        }

还是没到头，我们继续进入putUninterruptibly函数中。

private void putUninterruptibly(E eventObject) {
            boolean interrupted = false;
            try {
                while (true) {
                    try {
                        blockingQueue.put(eventObject);
                        break;
                    } catch (InterruptedException e) {
                        interrupted = true;
                    }
                }
            } finally {
                if (interrupted) {
                    Thread.currentThread().interrupt();
                }
            }
        }

一脸懵逼的发现，最后的结果是将事件放入blockingQueue阻塞队列中（BlockingQueue<E> blockingQueue）。那最终日志是在哪里打印的呢？别急我们全局搜素一下blockingQueue阻塞队列到底是用来做啥？

class Worker extends Thread {
    
            public void run() {
                AsyncAppenderBase<E> parent = AsyncAppenderBase.this;
                AppenderAttachableImpl<E> aai = parent.aai;
    
                // loop while the parent is started
                while (parent.isStarted()) {
                    try {
                        E e = parent.blockingQueue.take();
                        aai.appendLoopOnAppenders(e);
                    } catch (InterruptedException ie) {
                        break;
                    }
                }
    
                addInfo("Worker thread will flush remaining events before exiting. ");
    
                for (E e : parent.blockingQueue) {
                    aai.appendLoopOnAppenders(e);
                    parent.blockingQueue.remove(e);
                }
    
                aai.detachAndStopAllAppenders();
            }
        }

我们可以看到在一个线程中，会取出blockingQueue中的事件对象，然后调用aai.appendLoopOnAppenders(e)函数，通过io流将字符串输出到配置文件指定位置中。aai.appendLoopOnAppenders(e)里面的实现其实就是同步日志的实现，我们将配置文件修改为同步，然后一起看看aai.appendLoopOnAppenders(e)里面到底做了些什么？

<root level="INFO">
            
            
            
            
            
            
            <appender-ref ref="console"/>
            
            
            <appender-ref ref="file-error"/>
        </root>

this.append(eventObject)函数和之前异步日志输出的调用有所不同，同步日志会走如下所示的代码：

@Override
        protected void append(E eventObject) {
            if (!isStarted()) {
                return;
            }
    
            subAppend(eventObject);
        }

我们进入subAppend(eventObject)函数看看里面具体做了什么。

/**
         * Actual writing occurs here.
         * <p>
         * Most subclasses of <code>WriterAppender</code> will need to override this
         * method.
         * 
         * @since 0.9.0
         */
        protected void subAppend(E event) {
            if (!isStarted()) {
                return;
            }
            try {
                // this step avoids LBCLASSIC-139
                if (event instanceof DeferredProcessingAware) {
                    ((DeferredProcessingAware) event).prepareForDeferredProcessing();
                }
                // the synchronization prevents the OutputStream from being closed while we
                // are writing. It also prevents multiple threads from entering the same
                // converter. Converters assume that they are in a synchronized block.
                // lock.lock();
    
                byte[] byteArray = this.encoder.encode(event);
                writeBytes(byteArray);
    
            } catch (IOException ioe) {
                // as soon as an exception occurs, move to non-started state
                // and add a single ErrorStatus to the SM.
                this.started = false;
                addStatus(new ErrorStatus("IO failure in appender", this, ioe));
            }
        }

我们可以很明显的看到这个函数中就是将字符串输出到磁盘中，我们进入writeBytes(byteArray)看一下，此函数是否就是通过io流将日志打印到磁盘中。

private void writeBytes(byte[] byteArray) throws IOException {
            if(byteArray == null || byteArray.length == 0)
                return;
            
            lock.lock();
            try {
                this.outputStream.write(byteArray);
                if (immediateFlush) {
                    this.outputStream.flush();
                }
            } finally {
                lock.unlock();
            }
        }

this.outputStream.write(byteArray)函数就是将字符串对应的字节数组输出到指定位置。如图所示：

![image][image 3]

这边的this.outputStream对象也是在spring启动的时候初始化的，对象具体值会根据log配置文件所设置。

总结：

logback的日志打印原理就介绍到这边了，别看我们只是通过log.error()输出日志，但是内部却做了非常多的处理。开发虽然会用就可以了，但是如果不了解其内部实现原理，在出现百度不到bug的时候，就非常棘手了。好了今天林老师logback源码课程就介绍到这边了，谢谢童鞋们的观看。

[image]: /images/20230528/e6d5db3ddb764d289450351d46d28414.png
[image 1]: /images/20230528/273436c7c821431b82a85d4a6b70e2af.png
[image 2]: /images/20230528/b2f2ead39d5e4ecc865ce8ba1e1c2c9e.png
[image 3]: /images/20230528/90bc68142f2b48f08493084ed827ea12.png