聊一下 Java 的日志系列二

发表于 更新于 分类于 阅读次数： 阅读次数： Disqus：

log 初始化过程，首先是在启动类里会获取 logger

1
private static final Log logger = LogFactory.getLog(SpringApplication.class);

然后是

1
2
3
public static Log getLog(Class clazz) throws LogConfigurationException {
        return getFactory().getInstance(clazz);
    }

继续下去是
org.apache.commons.logging.impl.SLF4JLogFactory#getInstance(java.lang.Class)

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
public Log getInstance(Class clazz) throws LogConfigurationException {
    return this.getInstance(clazz.getName());
}
public Log getInstance(String name) throws LogConfigurationException {
    Log instance = (Log)this.loggerMap.get(name);
    if (instance != null) {
        return instance;
    } else {
        Logger slf4jLogger = LoggerFactory.getLogger(name);
        Object newInstance;
        if (slf4jLogger instanceof LocationAwareLogger) {
            newInstance = new SLF4JLocationAwareLog((LocationAwareLogger)slf4jLogger);
        } else {
            newInstance = new SLF4JLog(slf4jLogger);
        }

        Log oldInstance = (Log)this.loggerMap.putIfAbsent(name, newInstance);
        return (Log)(oldInstance == null ? newInstance : oldInstance);
    }
}

然后再往下处理就是 LoggerFactory.getLogger(name); 了，跟普通的获取 logger 一样

1
2
3
4
public static Logger getLogger(String name) {
    ILoggerFactory iLoggerFactory = getILoggerFactory();
    return iLoggerFactory.getLogger(name);
}

继续下去会先判断是否已初始化

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
public static ILoggerFactory getILoggerFactory() {
        if (INITIALIZATION_STATE == UNINITIALIZED) {
            synchronized (LoggerFactory.class) {
                if (INITIALIZATION_STATE == UNINITIALIZED) {
                    INITIALIZATION_STATE = ONGOING_INITIALIZATION;
                    performInitialization();
                }
            }
        }
        switch (INITIALIZATION_STATE) {
        case SUCCESSFUL_INITIALIZATION:
            return StaticLoggerBinder.getSingleton().getLoggerFactory();
        case NOP_FALLBACK_INITIALIZATION:
            return NOP_FALLBACK_FACTORY;
        case FAILED_INITIALIZATION:
            throw new IllegalStateException(UNSUCCESSFUL_INIT_MSG);
        case ONGOING_INITIALIZATION:
            // support re-entrant behavior.
            // See also http://jira.qos.ch/browse/SLF4J-97
            return SUBST_FACTORY;
        }
        throw new IllegalStateException("Unreachable code");
    }

第一次调用的话就会走到 org.slf4j.LoggerFactory#performInitialization 里面是先调用绑定，这也是 slf4j 门面模式的特点

1
2
3
4
5
6
private final static void performInitialization() {
    bind();
    if (INITIALIZATION_STATE == SUCCESSFUL_INITIALIZATION) {
        versionSanityCheck();
    }
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
private final static void bind() {
        try {
            Set<URL> staticLoggerBinderPathSet = null;
            // skip check under android, see also
            // http://jira.qos.ch/browse/SLF4J-328
            if (!isAndroid()) {
                staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
                reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
            }
            // the next line does the binding
            StaticLoggerBinder.getSingleton();
            INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
            reportActualBinding(staticLoggerBinderPathSet);
            fixSubstituteLoggers();
            replayEvents();
            // release all resources in SUBST_FACTORY
            SUBST_FACTORY.clear();
        } catch (NoClassDefFoundError ncde) {
            String msg = ncde.getMessage();
            if (messageContainsOrgSlf4jImplStaticLoggerBinder(msg)) {
                INITIALIZATION_STATE = NOP_FALLBACK_INITIALIZATION;
                Util.report("Failed to load class \"org.slf4j.impl.StaticLoggerBinder\".");
                Util.report("Defaulting to no-operation (NOP) logger implementation");
                Util.report("See " + NO_STATICLOGGERBINDER_URL + " for further details.");
            } else {
                failedBinding(ncde);
                throw ncde;
            }
        } catch (java.lang.NoSuchMethodError nsme) {
            String msg = nsme.getMessage();
            if (msg != null && msg.contains("org.slf4j.impl.StaticLoggerBinder.getSingleton()")) {
                INITIALIZATION_STATE = FAILED_INITIALIZATION;
                Util.report("slf4j-api 1.6.x (or later) is incompatible with this binding.");
                Util.report("Your binding is version 1.5.5 or earlier.");
                Util.report("Upgrade your binding to version 1.6.x.");
            }
            throw nsme;
        } catch (Exception e) {
            failedBinding(e);
            throw new IllegalStateException("Unexpected initialization failure", e);
        }
    }

非安卓环境会进入第一个 if 逻辑，先要去找static_logger_binder

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
static Set<URL> findPossibleStaticLoggerBinderPathSet() {
        // use Set instead of list in order to deal with bug #138
        // LinkedHashSet appropriate here because it preserves insertion order
        // during iteration
        Set<URL> staticLoggerBinderPathSet = new LinkedHashSet<URL>();
        try {
            ClassLoader loggerFactoryClassLoader = LoggerFactory.class.getClassLoader();
            Enumeration<URL> paths;
            if (loggerFactoryClassLoader == null) {
                paths = ClassLoader.getSystemResources(STATIC_LOGGER_BINDER_PATH);
            } else {
                paths = loggerFactoryClassLoader.getResources(STATIC_LOGGER_BINDER_PATH);
            }
            while (paths.hasMoreElements()) {
                URL path = paths.nextElement();
                staticLoggerBinderPathSet.add(path);
            }
        } catch (IOException ioe) {
            Util.report("Error getting resources from path", ioe);
        }
        return staticLoggerBinderPathSet;
    }

上面的 STATIC_LOGGER_BINDER_PATH
就是 org/slf4j/impl/StaticLoggerBinder.class 如果找不到在外层方法就会抛出 NoSuchMethodError 错误，然后就是通过 StaticLoggerBinder.getSingleton(); 获取 StaticLoggerBinder 实例了

1
2
3
4
public static StaticLoggerBinder getSingleton() {
    return SINGLETON;
}
private static StaticLoggerBinder SINGLETON = new StaticLoggerBinder();

比较重要的是这里的 static 代码块还有一个逻辑，就是下面这个初始化逻辑

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
static {
    SINGLETON.init();
}
void init() {
    try {
        try {
            new ContextInitializer(defaultLoggerContext).autoConfig();
        } catch (JoranException je) {
            Util.report("Failed to auto configure default logger context", je);
        }
        // logback-292
        if (!StatusUtil.contextHasStatusListener(defaultLoggerContext)) {
            StatusPrinter.printInCaseOfErrorsOrWarnings(defaultLoggerContext);
        }
        contextSelectorBinder.init(defaultLoggerContext, KEY);
        initialized = true;
    } catch (Exception t) { // see LOGBACK-1159
        Util.report("Failed to instantiate [" + LoggerContext.class.getName() + "]", t);
    }
}

上面的 defaultLoggerContext 也是通过静态代码块处理的

1
private LoggerContext defaultLoggerContext = new LoggerContext();

然后是调用 ch.qos.logback.classic.util.ContextInitializer#autoConfig 方法

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
public void autoConfig() throws JoranException {
        StatusListenerConfigHelper.installIfAsked(loggerContext);
        URL url = findURLOfDefaultConfigurationFile(true);
        if (url != null) {
            configureByResource(url);
        } else {
            Configurator c = EnvUtil.loadFromServiceLoader(Configurator.class);
            if (c != null) {
                try {
                    c.setContext(loggerContext);
                    c.configure(loggerContext);
                } catch (Exception e) {
                    throw new LogbackException(String.format("Failed to initialize Configurator: %s using ServiceLoader", c != null ? c.getClass()
                                    .getCanonicalName() : "null"), e);
                }
            } else {
                BasicConfigurator basicConfigurator = new BasicConfigurator();
                basicConfigurator.setContext(loggerContext);
                basicConfigurator.configure(loggerContext);
            }
        }
    }

前面会先查找配置文件路径
URL url = findURLOfDefaultConfigurationFile(true); 还是调用这个类内的 ch.qos.logback.classic.util.ContextInitializer#findURLOfDefaultConfigurationFile 方法

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
public URL findURLOfDefaultConfigurationFile(boolean updateStatus) {
    ClassLoader myClassLoader = Loader.getClassLoaderOfObject(this);
    URL url = findConfigFileURLFromSystemProperties(myClassLoader, updateStatus);
    if (url != null) {
        return url;
    }

    url = getResource(TEST_AUTOCONFIG_FILE, myClassLoader, updateStatus);
    if (url != null) {
        return url;
    }

    url = getResource(GROOVY_AUTOCONFIG_FILE, myClassLoader, updateStatus);
    if (url != null) {
        return url;
    }

    return getResource(AUTOCONFIG_FILE, myClassLoader, updateStatus);
}

才发现原来这里也是硬编码了文件名

1
2
3
4
5
6
7
public class ContextInitializer {

    final public static String GROOVY_AUTOCONFIG_FILE = "logback.groovy";
    final public static String AUTOCONFIG_FILE = "logback.xml";
    final public static String TEST_AUTOCONFIG_FILE = "logback-test.xml";
    final public static String CONFIG_FILE_PROPERTY = "logback.configurationFile";

如果不为空就调用了
ch.qos.logback.classic.util.ContextInitializer#configureByResource 这边是根据后缀判断处理方法

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
public void configureByResource(URL url) throws JoranException {
        if (url == null) {
            throw new IllegalArgumentException("URL argument cannot be null");
        }
        final String urlString = url.toString();
        if (urlString.endsWith("groovy")) {
            if (EnvUtil.isGroovyAvailable()) {
                // avoid directly referring to GafferConfigurator so as to avoid
                // loading groovy.lang.GroovyObject . See also http://jira.qos.ch/browse/LBCLASSIC-214
                GafferUtil.runGafferConfiguratorOn(loggerContext, this, url);
            } else {
                StatusManager sm = loggerContext.getStatusManager();
                sm.add(new ErrorStatus("Groovy classes are not available on the class path. ABORTING INITIALIZATION.", loggerContext));
            }
        } else if (urlString.endsWith("xml")) {
            JoranConfigurator configurator = new JoranConfigurator();
            configurator.setContext(loggerContext);
            configurator.doConfigure(url);
        } else {
            throw new LogbackException("Unexpected filename extension of file [" + url.toString() + "]. Should be either .groovy or .xml");
        }
    }

因为我们找到的是 logback.xml，所以走的是
ch.qos.logback.classic.joran.JoranConfigurator ，
然后调用了
ch.qos.logback.core.joran.GenericConfigurator#doConfigure(java.net.URL)
这个 GenericConfigurator 是 JoranConfigurator 的父类

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
public final void doConfigure(URL url) throws JoranException {
        InputStream in = null;
        try {
            informContextOfURLUsedForConfiguration(getContext(), url);
            URLConnection urlConnection = url.openConnection();
            // per http://jira.qos.ch/browse/LBCORE-105
            // per http://jira.qos.ch/browse/LBCORE-127
            urlConnection.setUseCaches(false);

            in = urlConnection.getInputStream();
            doConfigure(in, url.toExternalForm());
        } catch (IOException ioe) {
            String errMsg = "Could not open URL [" + url + "].";
            addError(errMsg, ioe);
            throw new JoranException(errMsg, ioe);
        } finally {
            if (in != null) {
                try {
                    in.close();
                } catch (IOException ioe) {
                    String errMsg = "Could not close input stream";
                    addError(errMsg, ioe);
                    throw new JoranException(errMsg, ioe);
                }
            }
        }
    }

然后继续调用
ch.qos.logback.core.joran.GenericConfigurator#doConfigure(java.io.InputStream, java.lang.String) 处理具体的内容，前面处理了内容获取，因为如果是走的 url 文件就需要从网络获取文件流，

1
2
3
4
5
public final void doConfigure(InputStream inputStream, String systemId) throws JoranException {
    InputSource inputSource = new InputSource(inputStream);
    inputSource.setSystemId(systemId);
    doConfigure(inputSource);
}

而实际的处理 xml 内容则是在
ch.qos.logback.core.joran.GenericConfigurator#doConfigure(org.xml.sax.InputSource)

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
public final void doConfigure(final InputSource inputSource) throws JoranException {

    long threshold = System.currentTimeMillis();
    // if (!ConfigurationWatchListUtil.wasConfigurationWatchListReset(context)) {
    // informContextOfURLUsedForConfiguration(getContext(), null);
    // }
    SaxEventRecorder recorder = new SaxEventRecorder(context);
    recorder.recordEvents(inputSource);
    doConfigure(recorder.saxEventList);
    // no exceptions a this level
    StatusUtil statusUtil = new StatusUtil(context);
    if (statusUtil.noXMLParsingErrorsOccurred(threshold)) {
        addInfo("Registering current configuration as safe fallback point");
        registerSafeConfiguration(recorder.saxEventList);
    }
}

需要解析 xml 了，先是调用 buildInterpreter 构建了 Interpreter

1
2
3
4
5
6
7
public void doConfigure(final List<SaxEvent> eventList) throws JoranException {
    buildInterpreter();
    // disallow simultaneous configurations of the same context
    synchronized (context.getConfigurationLock()) {
        interpreter.getEventPlayer().play(eventList);
    }
}

build 里还有一些逻辑，就是匹配后面要处理的规则集，就是要确认那些标签要处理

1
2
3
4
5
6
7
8
9
protected void buildInterpreter() {
        RuleStore rs = new SimpleRuleStore(context);
        addInstanceRules(rs);
        this.interpreter = new Interpreter(context, rs, initialElementPath());
        InterpretationContext interpretationContext = interpreter.getInterpretationContext();
        interpretationContext.setContext(context);
        addImplicitRules(interpreter);
        addDefaultNestedComponentRegistryRules(interpretationContext.getDefaultNestedComponentRegistry());
    }

第一步就是先 new 一个 ch.qos.logback.core.joran.spi.SimpleRuleStore 然后调用了 ch.qos.logback.classic.joran.JoranConfigurator#addInstanceRules 来添加规则，就是下面的，可以看到对于 logger,appender 这些的配置，其中前面点的父类也又一些规则 ,ch.qos.logback.core.joran.JoranConfiguratorBase 逻辑类似就不展开了，这里的规则就对应了后面的各种 Action，就是对应的处理逻辑

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
public void addInstanceRules(RuleStore rs) {
    // parent rules already added
    super.addInstanceRules(rs);

    rs.addRule(new ElementSelector("configuration"), new ConfigurationAction());

    rs.addRule(new ElementSelector("configuration/contextName"), new ContextNameAction());
    rs.addRule(new ElementSelector("configuration/contextListener"), new LoggerContextListenerAction());
    rs.addRule(new ElementSelector("configuration/insertFromJNDI"), new InsertFromJNDIAction());
    rs.addRule(new ElementSelector("configuration/evaluator"), new EvaluatorAction());

    rs.addRule(new ElementSelector("configuration/appender/sift"), new SiftAction());
    rs.addRule(new ElementSelector("configuration/appender/sift/*"), new NOPAction());

    rs.addRule(new ElementSelector("configuration/logger"), new LoggerAction());
    rs.addRule(new ElementSelector("configuration/logger/level"), new LevelAction());

    rs.addRule(new ElementSelector("configuration/root"), new RootLoggerAction());
    rs.addRule(new ElementSelector("configuration/root/level"), new LevelAction());
    rs.addRule(new ElementSelector("configuration/logger/appender-ref"), new AppenderRefAction<ILoggingEvent>());
    rs.addRule(new ElementSelector("configuration/root/appender-ref"), new AppenderRefAction<ILoggingEvent>());

    // add if-then-else support
    rs.addRule(new ElementSelector("*/if"), new IfAction());
    rs.addRule(new ElementSelector("*/if/then"), new ThenAction());
    rs.addRule(new ElementSelector("*/if/then/*"), new NOPAction());
    rs.addRule(new ElementSelector("*/if/else"), new ElseAction());
    rs.addRule(new ElementSelector("*/if/else/*"), new NOPAction());

    // add jmxConfigurator only if we have JMX available.
    // If running under JDK 1.4 (retrotranslateed logback) then we
    // might not have JMX.
    if (PlatformInfo.hasJMXObjectName()) {
        rs.addRule(new ElementSelector("configuration/jmxConfigurator"), new JMXConfiguratorAction());
    }
    rs.addRule(new ElementSelector("configuration/include"), new IncludeAction());

    rs.addRule(new ElementSelector("configuration/consolePlugin"), new ConsolePluginAction());

    rs.addRule(new ElementSelector("configuration/receiver"), new ReceiverAction());

}

然后调用了 interpreter 的 eventPlayer 处理 xml 的各个标签

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
public void play(List<SaxEvent> aSaxEventList) {
        eventList = aSaxEventList;
        SaxEvent se;
        for (currentIndex = 0; currentIndex < eventList.size(); currentIndex++) {
            se = eventList.get(currentIndex);

            if (se instanceof StartEvent) {
                interpreter.startElement((StartEvent) se);
                // invoke fireInPlay after startElement processing
                interpreter.getInterpretationContext().fireInPlay(se);
            }
            if (se instanceof BodyEvent) {
                // invoke fireInPlay before characters processing
                interpreter.getInterpretationContext().fireInPlay(se);
                interpreter.characters((BodyEvent) se);
            }
            if (se instanceof EndEvent) {
                // invoke fireInPlay before endElement processing
                interpreter.getInterpretationContext().fireInPlay(se);
                interpreter.endElement((EndEvent) se);
            }

        }
    }

接下去就在 startElement 中调用会先获取 getApplicableActionList 适配的 Action， callBeginAction

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
private void startElement(String namespaceURI, String localName, String qName, Attributes atts) {

        String tagName = getTagName(localName, qName);
        elementPath.push(tagName);

        if (skip != null) {
            // every startElement pushes an action list
            pushEmptyActionList();
            return;
        }

        List<Action> applicableActionList = getApplicableActionList(elementPath, atts);
        if (applicableActionList != null) {
            actionListStack.add(applicableActionList);
            callBeginAction(applicableActionList, tagName, atts);
        } else {
            // every startElement pushes an action list
            pushEmptyActionList();
            String errMsg = "no applicable action for [" + tagName + "], current ElementPath  is [" + elementPath + "]";
            cai.addError(errMsg);
        }
    }

里面就是用了 ruleStore 来判断是否适配，并且取出对应的 Action

1
2
3
4
5
6
7
8
9
10
List<Action> getApplicableActionList(ElementPath elementPath, Attributes attributes) {
    List<Action> applicableActionList = ruleStore.matchActions(elementPath);

    // logger.debug("set of applicable patterns: " + applicableActionList);
    if (applicableActionList == null) {
        applicableActionList = lookupImplicitAction(elementPath, attributes, interpretationContext);
    }

    return applicableActionList;
}

比如我这边往下处理，通过规则匹配拿到了 LoggerAction, 然后调用 Action.begin 方法

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
void callBeginAction(List<Action> applicableActionList, String tagName, Attributes atts) {
        if (applicableActionList == null) {
            return;
        }

        Iterator<Action> i = applicableActionList.iterator();
        while (i.hasNext()) {
            Action action = (Action) i.next();
            // now let us invoke the action. We catch and report any eventual
            // exceptions
            try {
                action.begin(interpretationContext, tagName, atts);
            } catch (ActionException e) {
                skip = elementPath.duplicate();
                cai.addError("ActionException in Action for tag [" + tagName + "]", e);
            } catch (RuntimeException e) {
                skip = elementPath.duplicate();
                cai.addError("RuntimeException in Action for tag [" + tagName + "]", e);
            }
        }
    }

就是下面这个

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
public void begin(InterpretationContext ec, String name, Attributes attributes) {
        // Let us forget about previous errors (in this object)
        inError = false;
        logger = null;

        LoggerContext loggerContext = (LoggerContext) this.context;

        String loggerName = ec.subst(attributes.getValue(NAME_ATTRIBUTE));

        if (OptionHelper.isEmpty(loggerName)) {
            inError = true;
            String aroundLine = getLineColStr(ec);
            String errorMsg = "No 'name' attribute in element " + name + ", around " + aroundLine;
            addError(errorMsg);
            return;
        }

        logger = loggerContext.getLogger(loggerName);

        String levelStr = ec.subst(attributes.getValue(LEVEL_ATTRIBUTE));

        if (!OptionHelper.isEmpty(levelStr)) {
            if (ActionConst.INHERITED.equalsIgnoreCase(levelStr) || ActionConst.NULL.equalsIgnoreCase(levelStr)) {
                addInfo("Setting level of logger [" + loggerName + "] to null, i.e. INHERITED");
                logger.setLevel(null);
            } else {
                Level level = Level.toLevel(levelStr);
                addInfo("Setting level of logger [" + loggerName + "] to " + level);
                logger.setLevel(level);
            }
        }

        String additivityStr = ec.subst(attributes.getValue(ActionConst.ADDITIVITY_ATTRIBUTE));
        if (!OptionHelper.isEmpty(additivityStr)) {
            boolean additive = OptionHelper.toBoolean(additivityStr, true);
            addInfo("Setting additivity of logger [" + loggerName + "] to " + additive);
            logger.setAdditive(additive);
        }
        ec.pushObject(logger);
    }

这里就会处理 logger 获取逻辑

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
public final Logger getLogger(final String name) {

        if (name == null) {
            throw new IllegalArgumentException("name argument cannot be null");
        }

        // if we are asking for the root logger, then let us return it without
        // wasting time
        if (Logger.ROOT_LOGGER_NAME.equalsIgnoreCase(name)) {
            return root;
        }

        int i = 0;
        Logger logger = root;

        // check if the desired logger exists, if it does, return it
        // without further ado.
        Logger childLogger = (Logger) loggerCache.get(name);
        // if we have the child, then let us return it without wasting time
        if (childLogger != null) {
            return childLogger;
        }

        // if the desired logger does not exist, them create all the loggers
        // in between as well (if they don't already exist)
        String childName;
        while (true) {
            int h = LoggerNameUtil.getSeparatorIndexOf(name, i);
            if (h == -1) {
                childName = name;
            } else {
                childName = name.substring(0, h);
            }
            // move i left of the last point
            i = h + 1;
            synchronized (logger) {
                childLogger = logger.getChildByName(childName);
                if (childLogger == null) {
                    childLogger = logger.createChildByName(childName);
                    loggerCache.put(childName, childLogger);
                    incSize();
                }
            }
            logger = childLogger;
            if (h == -1) {
                return childLogger;
            }
        }
    }

如果从 loggerCache 中能取到就直接获取，如果不能就会去创建