[slf4j+log] 源码解析

Posted 2021-02-16 mianteno

slf4j: The Simple Logging Facade for java即 java简单的日志门面。
统一定义了一系列的日志接口，使用户可以使用统一的接口来记录日志。logback,log4j等框架都实现了这些接口，启动时动态地决定真正的日志框架。
本文以slf4j+logback的源码来讲解整个绑定和打印日志的流程。

手动阅读目录如下：

• 绑定日志框架
• 解析配置文件获取LoggerFactory：对于logback而言就是LoggerContext
• 获取Logger：在LoggerAction的begin方法中会将创建的logger对象缓存到loggerCache中and logger的childList结构中;后续的AppenderRefAction中，会将appender添加进来
• 打印日志：分为同步的Appender和异步的Appender

可用的日志框架依赖如下:

 1         <dependency>
 2             <groupId>org.slf4j</groupId>
 3             <artifactId>slf4j-simple</artifactId>
 4             <version>1.7.5</version>
 5         </dependency>
 6         <dependency>
 7             <groupId>org.slf4j</groupId>
 8             <artifactId>slf4j-log4j12</artifactId>
 9             <version>1.7.25</version>
10         </dependency>
11 
12         <dependency>
13             <groupId>org.slf4j</groupId>
14             <artifactId>slf4j-jdk14</artifactId>
15             <version>1.7.25</version>
16         </dependency>
17         <dependency>
18             <groupId>ch.qos.logback</groupId>
19             <artifactId>logback-classic</artifactId>
20             <scope>runtime</scope>
21         </dependency>

View Code

如何使用slf4j的示例代码如下(配合logback的配置文件):

 1 import org.slf4j.Logger;
 2 import org.slf4j.LoggerFactory;
 3 
 4 
 5 public class LoggerTest {
 6 
 7     private static final Logger logger = LoggerFactory.getLogger(LoggerTest.class);
 8 
 9     public static void main(String[] args){
10         logger.info("hello world！");
11     }
12 
13 }

View Code

本文以[示例]logback.xml的配置文件为例：

 1  <!-- DEBUG级别日志 appender -->
 2     <appender name="DEBUG_LOG" class="ch.qos.logback.core.rolling.RollingFileAppender" additivity="true">
 3         <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
 4             <!-- 按天回滚 daily -->
 5             <fileNamePattern>/Users/tanling/saveDir/logs/%d{yyyy-MM-dd}/debug-log1.log</fileNamePattern>
 6             <!-- 日志最大的历史 60天 -->
 7             <maxHistory>60</maxHistory>
 8         </rollingPolicy>
 9         <encoder>
10             <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern>
11         </encoder>
12     </appender>
13 
14 
15     <appender name="DEBUG_LOG_ASYNC" class= "ch.qos.logback.classic.AsyncAppender">
16         <!-- 不丢失日志.默认的,如果队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志 -->
17         <discardingThreshold >0</discardingThreshold>
18         <!-- 更改默认的队列的深度,该值会影响性能.默认值为256 -->
19         <queueSize>2048</queueSize>
20         <neverBlock>true</neverBlock>
21         <includeCallerData>true</includeCallerData>
22         <maxFlushTime>3000</maxFlushTime>
23         <!-- 添加附加的appender,最多只能添加一个 -->
24         <appender-ref ref ="DEBUG_LOG"/>
25     </appender>
26 
27     <!-- root级别   DEBUG -->
28     <root level="INFO">
29         <!-- 控制台输出 -->
30         <appender-ref ref="STDOUT" />
31         <!-- 文件输出 -->
32         <appender-ref ref="DEBUG_LOG" />
33     </root>
34 
35     <logger name="org.foo.demo" additivity="true" >
36         <level value="INFO"/>
37         <appender-ref ref="DEBUG_LOG"/>
38     </logger>

View Code

绑定日志框架

点开LoggerFactory.getLogger的源码：

 1  //LoggerFactory
 2  public static Logger getLogger(String name) {
 3    ILoggerFactory iLoggerFactory = getILoggerFactory();
 4    return iLoggerFactory.getLogger(name);
 5  }
 6  public static ILoggerFactory getILoggerFactory() {
 7    if (INITIALIZATION_STATE == UNINITIALIZED) {
 8      INITIALIZATION_STATE = ONGOING_INITIALIZATION;
 9      // 初始化 这里是后续分析代码的核心
10      performInitialization();
11    }
12    switch (INITIALIZATION_STATE) {
13      case SUCCESSFUL_INITIALIZATION:
14        // 初始化成功以后，返回StaticLoggerBinder的单例的loggerfactory
15        return StaticLoggerBinder.getSingleton().getLoggerFactory();
16      case NOP_FALLBACK_INITIALIZATION:
17        return NOP_FALLBACK_FACTORY;
18      case FAILED_INITIALIZATION:
19        throw new IllegalStateException(UNSUCCESSFUL_INIT_MSG);
20      case ONGOING_INITIALIZATION:
21        // support re-entrant behavior.
22        // See also http://bugzilla.slf4j.org/show_bug.cgi?id=106
23        return TEMP_FACTORY;
24    }
25    throw new IllegalStateException("Unreachable code");
26  }
27
28  private final static void performInitialization() {
29    // 绑定，这里是绑定真正的日志框架
30    bind();
31    if (INITIALIZATION_STATE == SUCCESSFUL_INITIALIZATION) {
32      versionSanityCheck();
33    }
34  }
35
36  // ?? 绑定是重点
37  private final static void bind() {
38    try {
39      // 通过类加载器加载 org/slf4j/impl/StaticLoggerBinder.class 
40      Set<URL> staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
41      reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
42      // the next line does the binding
43      // ?? 解析logback配置文件，获取真正的LoggerFactory
44      StaticLoggerBinder.getSingleton();
45      INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
46      reportActualBinding(staticLoggerBinderPathSet);
47      fixSubstitutedLoggers();
48    } catch (NoClassDefFoundError ncde) {
49     // 代码略去
50    } catch (java.lang.NoSuchMethodError nsme) {
51     // 代码略去
52    }
53  }

源码解析:
当运行getILoggerFactory方法的时候，首先会执行初始化获取到真正的LoggerFactory,然后返回。bind是重点。
bind里面做了以下几件事情：

• 通过类加载器加载classpath中的org/slf4j/impl/StaticLoggerBinder.class
• StaticLoggerBinder.getSingleton 解析logback配置文件，获取真正的LoggerFactory
• 检查classpath中是否导入了多个日志框架

slf4j api旨在一次只与一个基础日志框架绑定。如果类路径上存在多个绑定，则slf4j将发出警告，列出这些绑定的位置。如果类路径上有多个绑定，请选择一个且只能使用一个绑定，并删除其他绑定。即使存在多个绑定，slf4j也会选择一个日志框架实现并与之绑定。https://www.slf4j.org/codes.html#multiple_bindings

获取LoggerContext

下面来介绍StaticLoggerBinder的过程(以logback为例)

 1    void init() {
 2        try {
 3            try {
 4               // 通过ContextInitializer来解析logback的配置文件，解析的内容记录到LoggerContext中
 5                new ContextInitializer(defaultLoggerContext).autoConfig();
 6            } catch (JoranException je) {
 7                Util.report("Failed to auto configure default logger context", je);
 8            }
 9            // logback-292
10            if (!StatusUtil.contextHasStatusListener(defaultLoggerContext)) {
11                StatusPrinter.printInCaseOfErrorsOrWarnings(defaultLoggerContext);
12            }
13            // 将LoggerContext存储到 contextSelectorBinder.getContextSelector()中
14            contextSelectorBinder.init(defaultLoggerContext, KEY);
15            initialized = true;
16        } catch (Throwable t) {
17            // we should never get here
18            Util.report("Failed to instantiate [" + LoggerContext.class.getName() + "]", t);
19        }
20    }
21
22public ILoggerFactory getLoggerFactory() {
23        if (!initialized) {
24            return defaultLoggerContext;
25        }
26
27        if (contextSelectorBinder.getContextSelector() == null) {
28            throw new IllegalStateException("contextSelector cannot be null. See also " + NULL_CS_URL);
29        }
30        // 这里获取到的LoggerFactroy实际上就是LoggerContext
31        return contextSelectorBinder.getContextSelector().getLoggerContext();
32    }

代码解析：
上面两个方法，我们结合起来看。

• init()方法中，通过ContextInitializer来解析logback的配置文件，解析的内容入LoggerContext中。并且将该内容存储到了contextSelectorBinder.getContextSelector()中。
• getLoggerFactory实际返回的就是LoggerContext。

接着来分析是如何解析logback配置文件

 1// ContextInitializer
 2    public void autoConfig() throws JoranException {
 3        StatusListenerConfigHelper.installIfAsked(loggerContext);
 4        // 获取到logback的配置文件
 5        URL url = findURLOfDefaultConfigurationFile(true);
 6        if (url != null) {
 7            // 存在配置文件的时候解析
 8            configureByResource(url);
 9        } else {
10            // 不存在配置文件的时候的处理
11            Configurator c = EnvUtil.loadFromServiceLoader(Configurator.class);
12            if (c != null) {
13                try {
14                    c.setContext(loggerContext);
15                    c.configure(loggerContext);
16                } catch (Exception e) {
17                    throw new LogbackException(String.format("Failed to initialize Configurator: %s using ServiceLoader", c != null ? c.getClass()
18                                    .getCanonicalName() : "null"), e);
19                }
20            } else {
21                BasicConfigurator basicConfigurator = new BasicConfigurator();
22                basicConfigurator.setContext(loggerContext);
23                basicConfigurator.configure(loggerContext);
24            }
25        }
26    }

代码解析：
获取logback配置文件，获取到则进行配置文件的解析。获取的顺序是这样的：

1    // ②
2    final public static String GROOVY_AUTOCONFIG_FILE = "logback.groovy";
3    // ④
4    final public static String AUTOCONFIG_FILE = "logback.xml";
5    // ③
6    final public static String TEST_AUTOCONFIG_FILE = "logback-test.xml";
7    // ①
8    final public static String CONFIG_FILE_PROPERTY = "logback.configurationFile";

最终落到代码EventPlayer上

1// ContextInitializer
2else if (urlString.endsWith("xml")) {
3            JoranConfigurator configurator = new JoranConfigurator();
4            configurator.setContext(loggerContext);
5            configurator.doConfigure(url);
6        } 
 1    public void play(List<SaxEvent> aSaxEventList) {
 2        eventList = aSaxEventList;
 3        SaxEvent se;
 4        for (currentIndex = 0; currentIndex < eventList.size(); currentIndex++) {
 5            se = eventList.get(currentIndex);
 6
 7            if (se instanceof StartEvent) {
 8                interpreter.startElement((StartEvent) se);
 9                // invoke fireInPlay after startElement processing
10                interpreter.getInterpretationContext().fireInPlay(se);
11            }
12            if (se instanceof BodyEvent) {
13                // invoke fireInPlay before characters processing
14                interpreter.getInterpretationContext().fireInPlay(se);
15                interpreter.characters((BodyEvent) se);
16            }
17            if (se instanceof EndEvent) {
18                // invoke fireInPlay before endElement processing
19                interpreter.getInterpretationContext().fireInPlay(se);
20                interpreter.endElement((EndEvent) se);
21            }
22
23        }
24    }

代码解析:
将logback配置文件中的标签会被解析成List。是如何解析的：
标签以"<"为开头的，会解析成StartEven事件。 标签以"<杠"为开头的，会被解析成EndEvent事件。 在"<"xx>"body"<杠xxx>"标签中的body内容，会被解析成BodyEvent事件。
如图参见debug的结果，每个<的标签都是成对出现的，中间是BodyEvent。

对于不同的标签，均会有StartEvent和EndEvent事件。每个标签都有一个对应的Action，其中有begin和end方法，分别对应上面StartEvent和EndEvent事件的处理。
其中BodyEvent对应于Action中的body方法。

标签	处理标签的StartEvent和EndEvent的Action
appender	AppenderAction
root	RootLoggerAction
logger	LoggerAction
appender-ref	AppenderRefAction
属性标签(比如:rollingPolicy)	NestedComplexPropertyIA
属性标签(比如:fileNamePattern)	NestedBasicPropertyIA

下面主要来介绍下各标签的处理：
其中以示例logback.xml为例：

红色标的数字代表appender=DEBUG_LOG的执行路径。青色数字顺序代表appender=DEBUG_LOG_ASYNC的执行顺序。黄色的数字代表logger=org.foo.demo的执行顺序。紫色的数字代表root的执行顺序。
核心思想就是利用栈的特性，标签开始的是将对象压入栈，结束的时候将对象从栈中出栈，处理内部的标签时只需要从栈中peek一个对象即是其父对象，处理完了后作为属性设置进去。最终所有key=loggerName,value=logger对象都会缓存到LoggerContext中。

获取Logger

 1    public final Logger getLogger(final String name) {
 2
 3        if (name == null) {
 4            throw new IllegalArgumentException("name argument cannot be null");
 5        }
 6
 7        // if we are asking for the root logger, then let us return it without
 8        // wasting time
 9        if (Logger.ROOT_LOGGER_NAME.equalsIgnoreCase(name)) {
10            return root;
11        }
12
13        int i = 0;
14        Logger logger = root;
15
16        // check if the desired logger exists, if it does, return it
17        // without further ado.
18        // 最终所有的key=loggerName,value=logger实例都会缓存在LoggerContext中的loggerCache中
19        Logger childLogger = (Logger) loggerCache.get(name);
20        // if we have the child, then let us return it without wasting time
21        if (childLogger != null) {
22            return childLogger;
23        }
24
25        // if the desired logger does not exist, them create all the loggers
26        // in between as well (if they don‘t already exist)
27        String childName;
28        // 获取Logger的逻辑
29        while (true) {
30            int h = LoggerNameUtil.getSeparatorIndexOf(name, i);
31            if (h == -1) {
32                childName = name;
33            } else {
34                childName = name.substring(0, h);
35            }
36            // move i left of the last point
37            i = h + 1;
38            synchronized (logger) {
39                childLogger = logger.getChildByName(childName);
40                if (childLogger == null) {
41                    childLogger = logger.createChildByName(childName);
42                    loggerCache.put(childName, childLogger);
43                    incSize();
44                }
45            }
46            logger = childLogger;
47            if (h == -1) {
48                return childLogger;
49            }
50        }
51    }

代码解析：
当指定的loggerName中没有点号的时候，从rootLogger中获取childLogger,没有的场合，则新建一个Logger对象，其parentLogger为rootLogger。
指定一个类名的时候，loggerName为该类的全类名。
比如org.foo.demo.LoggerTest,
先查找loggerName=org的logger对象；再查找loggerName=org.foo的logger实例；直至创建loggerName=org.foo.demo.LoggerTest的logger对象。
有的场合直接从logger的chidlist结构中获取，这是在解析LoggerAction的时候缓存起来的。
剧透一下，执行打印的时候，会追溯logger的父logger执行appender。

利用Logger打印日志(同步&异步)

 1    private void buildLoggingEventAndAppend(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params,
 2                    final Throwable t) {
 3        // 会将方法的调用参数level 消息 params 异常封装成LoggerEvent
 4        LoggingEvent le = new LoggingEvent(localFQCN, this, level, msg, t, params);
 5        le.setMarker(marker);
 6        callAppenders(le);
 7    }
 8
 9    public void callAppenders(ILoggingEvent event) {
10        int writes = 0;
11        // 这里是上述的剧透内容，会遍历执行logger.parent的appender
12        // additive为配置文件中配置的内容，默认为true，当配置为false的时候，会终止追溯其父logger
13        for (Loogger l = this; l != null; l = l.parent) {
14            writes += l.appendLoopOnAppenders(event);
15            if (!l.additive) {
16                break;
17            }
18        }
19        // No appenders in hierarchy
20        if (writes == 0) {
21            loggerContext.noAppenderDefinedWarning(this);
22        }
23    }
24    // logger的aai是AppenderAttachableImpl对象，其中持有多个Appender的list
25    private int appendLoopOnAppenders(ILoggingEvent event) {
26        if (aai != null) {
27            return aai.appendLoopOnAppenders(event);
28        } else {
29            return 0;
30        }
31    }
32    public int appendLoopOnAppenders(E e) {
33        int size = 0;
34        // 找到logger对应的Appender，执行器logger方法
35        for (Appender<E> appender : appenderList) {
36            appender.doAppend(e);
37            size++;
38        }
39        return size;
40    }

代码解析：
将方法的参数封装成LoggingEvent对象，从指定名称的loggery追溯logger的parentLogger，通过logger中持有的appender来执行。

AppenderAction的end方法中会执行启动：

 1    public void end(InterpretationContext ec, String name) {
 2        if (inError) {
 3            return;
 4        }
 5        // 这里启动appender
 6        if (appender instanceof LifeCycle) {
 7            ((LifeCycle) appender).start();
 8        }
 9
10        Object o = ec.peekObject();
11
12        if (o != appender) {
13            addWarn("The object at the of the stack is not the appender named [" + appender.getName() + "] pushed earlier.");
14        } else {
15            ec.popObject();
16        }
17    }

RollingFileAppender(同步)

1    public void start() {
2        // 部分代码略
3        // 进行一堆check，然后appender的文件名创建文件，然后打开文件流，将日志以append的方式追加到文件中
4        currentlyActiveFile = new File(getFile());
5        addInfo("Active log file name: " + getFile());
6        super.start();
7    }

AsyncAppender(异步)

 1// AsyncAppenderBase
 2    @Override
 3    public void start() {
 4        if (isStarted())
 5            return;
 6        if (appenderCount == 0) {
 7            addError("No attached appenders found.");
 8            return;
 9        }
10        if (queueSize < 1) {
11            addError("Invalid queue size [" + queueSize + "]");
12            return;
13        }
14        blockingQueue = new ArrayBlockingQueue<E>(queueSize);
15
16        if (discardingThreshold == UNDEFINED)
17            discardingThreshold = queueSize / 5;
18        addInfo("Setting discardingThreshold to " + discardingThreshold);
19        worker.setDaemon(true);
20        worker.setName("AsyncAppender-Worker-" + getName());
21        // make sure this instance is marked as "started" before staring the worker Thread
22        super.start();
23        worker.start();
24    }
25
26    @Override
27    protected void append(E eventObject) {
28        // 当队列空间所剩无几的时候 & 日志级别(INFO,DEBU,TRACE)<=INFO的场合，消息直接丢弃
29        if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) {
30            return;
31        }
32        preprocess(eventObject);
33        put(eventObject);
34    }
35
36    private void put(E eventObject) {
37        if (neverBlock) {
38            blockingQueue.offer(eventObject);
39        } else {
40            try {
41                blockingQueue.put(eventObject);
42            } catch (InterruptedException e) {
43                // Interruption of current thread when in doAppend method should not be consumed
44                // by AsyncAppender
45                Thread.currentThread().interrupt();
46            }
47        }
48    }

代码解析：

• 创建一个ArrayBlockingQueue队列，用于存放创建的LoggingEvent，其中neverBlock为配置文件中指定，true的场合，满了也不阻塞直接返回; false的场合，满了则阻塞，直至event被消费。
• 创建了一个工作线程Worker

 1    class Worker extends Thread {
 2
 3        public void run() {
 4            AsyncAppenderBase<E> parent = AsyncAppenderBase.this;
 5            AppenderAttachableImpl<E> aai = parent.aai;
 6
 7            // loop while the parent is started
 8            while (parent.isStarted()) {
 9                try {
10                    E e = parent.blockingQueue.take();
11                    aai.appendLoopOnAppenders(e);
12                } catch (InterruptedException ie) {
13                    break;
14                }
15            }
16
17            addInfo("Worker thread will flush remaining events before exiting. ");
18
19            for (E e : parent.blockingQueue) {
20                aai.appendLoopOnAppenders(e);
21                parent.blockingQueue.remove(e);
22            }
23
24            aai.detachAndStopAllAppenders();
25        }
26    }

代码解析:
asyncAppender中的aai就是同步的appender，这里只要appender开启中，会从blockingQueue队列中取出LoggingEvent交给普通的appender来执行。

以上。

 

更多源码分析，关注公众号??????