SpringBoot LoggingSystem相关源码分析

SpringBoot版本

1.5.17-RELEASE

友情提示

源码分析过程篇幅较长，赶时间的同学可以直接拖到最后看整体流程图，常见问题和最佳实践

不说废话，直接正题

org.springframework.boot.logging.LoggingApplicationListener——核心类，通过监听不同的事件来做出不同的响应：

    @Override
    public void onApplicationEvent(ApplicationEvent event) {
        if (event instanceof ApplicationStartingEvent) {
            onApplicationStartingEvent((ApplicationStartingEvent) event);
        }
        else if (event instanceof ApplicationEnvironmentPreparedEvent) {
            onApplicationEnvironmentPreparedEvent(
                    (ApplicationEnvironmentPreparedEvent) event);
        }
        else if (event instanceof ApplicationPreparedEvent) {
            onApplicationPreparedEvent((ApplicationPreparedEvent) event);
        }
        else if (event instanceof ContextClosedEvent && ((ContextClosedEvent) event)
                .getApplicationContext().getParent() == null) {
            onContextClosedEvent();
        }
        else if (event instanceof ApplicationFailedEvent) {
            onApplicationFailedEvent();
        }
    }

下面会根据不同的事件依次来分析

ApplicationStartingEvent

这个事件是SpringBoot容器启动过程中最早发出的事件，告诉everybody开始启动了。

此时LoggingApplicationListener对应的动作也很简单，调用LoggingSystem的beforeInitialize()方法：

    private void onApplicationStartingEvent(ApplicationStartingEvent event) {
        this.loggingSystem = LoggingSystem
                .get(event.getSpringApplication().getClassLoader());
        this.loggingSystem.beforeInitialize();
    }

LoggingSystem是SpringBoot对日志系统的抽象，是一个顶层的抽象类，我们先来看下它的整体结构：

一眼就看到我们用的日志框架Log4J2，那就先从Slf4JLoggingSystem和Log4J2LoggingSystem的beforeInitialize()方法来入手：

    // method in Log4J2LoggingSystem 
    @Override
    public void beforeInitialize() {
        LoggerContext loggerContext = getLoggerContext();
        // 这块做了一个去重保护
        if (isAlreadyInitialized(loggerContext)) {
            return;
        }
        super.beforeInitialize();
        loggerContext.getConfiguration().addFilter(FILTER);
    }
    
    // method in Slf4JLoggingSystem
    @Override
    public void beforeInitialize() {
        // 这里父类的实现是个空方法，就不列了
        super.beforeInitialize();
        configureJdkLoggingBridgeHandler();
    }
    
    // jul to slf4j bridge
    private void configureJdkLoggingBridgeHandler() {
        try {
            if (isBridgeHandlerAvailable()) {
                removeJdkLoggingBridgeHandler();
                SLF4JBridgeHandler.install();
            }
        }
        catch (Throwable ex) {
            // Ignore. No java.util.logging bridge is installed.
        }
    }

Slf4JLoggingSystem只做了一件事，就是注册SLF4JBridgeHandler，这个是为了把jul日志框架打印的日志代理到slf4j的接口

而Log4J2LoggingSystem其实主要也就一个目的——注册一个特殊的Filter

这个Filter做了什么呢？

    private static final Filter FILTER = new AbstractFilter() {

        @Override
        public Result filter(LogEvent event) {
            return Result.DENY;
        }

        @Override
        public Result filter(Logger logger, Level level, Marker marker, Message msg,
                Throwable t) {
            return Result.DENY;
        }

        @Override
        public Result filter(Logger logger, Level level, Marker marker, Object msg,
                Throwable t) {
            return Result.DENY;
        }

        @Override
        public Result filter(Logger logger, Level level, Marker marker, String msg,
                Object... params) {
            return Result.DENY;
        }

    };

看起来应该是想过滤掉所有日志，因为Filter是添加在Configuration上的，所有的Logger都会受到这个Filter的影响。

ApplicationEnvironmentPreparedEvent

这个阶段配置文件全部都加载完成，环境变量也都构建完毕。此时可以初始化日志系统（LoggingSystem）了。因为SpringBoot支持LoggingSystem相关的配置（ https://docs.spring.io/spring-boot/docs/1.5.17.RELEASE/reference/htmlsingle/#boot-features-logging ）所以肯定要先把配置加载完才能开始初始化日志系统。看下这个阶段对应有哪些动作：

    private void onApplicationEnvironmentPreparedEvent(
            ApplicationEnvironmentPreparedEvent event) {
        if (this.loggingSystem == null) {
            this.loggingSystem = LoggingSystem
                    .get(event.getSpringApplication().getClassLoader());
        }
        initialize(event.getEnvironment(), event.getSpringApplication().getClassLoader());
    }
    
    protected void initialize(ConfigurableEnvironment environment,
            ClassLoader classLoader) {
        new LoggingSystemProperties(environment).apply();
        // SpringBoot定义的输出日志文件
        LogFile logFile = LogFile.get(environment);
        if (logFile != null) {
            logFile.applyToSystemProperties();
        }
        initializeEarlyLoggingLevel(environment);
        initializeSystem(environment, this.loggingSystem, logFile);
        initializeFinalLoggingLevels(environment, this.loggingSystem);
        registerShutdownHookIfNecessary(environment, this.loggingSystem);
    }

总结起来就是这么几件事：

初始化底层日志框架initializeSystem
根据SpringBoot日志系统的配置来做一些调整
1. 简易的输出日志文件机制LogFile
2. Logger的Level调整机制initializeEarlyLoggingLevel/initializeFinalLoggingLevels
3. 注册ShutdownHookregisterShutdownHookIfNecessary

我们按照这个脉络来分析一下源代码

初始化底层日志框架

先看下初始化底层日志框架：

    private void initializeSystem(ConfigurableEnvironment environment,
            LoggingSystem system, LogFile logFile) {
        LoggingInitializationContext initializationContext = new LoggingInitializationContext(
                environment);
        String logConfig = environment.getProperty(CONFIG_PROPERTY);
        // 如果没有指定配置文件
        if (ignoreLogConfig(logConfig)) {
            system.initialize(initializationContext, null, logFile);
        }
        else {
            try {
                ResourceUtils.getURL(logConfig).openStream().close();
                // 具体日志框架的initialize实现
                system.initialize(initializationContext, logConfig, logFile);
            }
            catch (Exception ex) {
                // NOTE: We can't use the logger here to report the problem
                System.err.println("Logging system failed to initialize "
                        + "using configuration from '" + logConfig + "'");
                ex.printStackTrace(System.err);
                throw new IllegalStateException(ex);
            }
        }
    }

这里只是取到配置文件的路径，之后就委托给具体的日志系统来处理了，还是以Log4J2LoggingSystem为例来看一下：

    @Override
    public void initialize(LoggingInitializationContext initializationContext,
            String configLocation, LogFile logFile) {
        LoggerContext loggerContext = getLoggerContext();
        if (isAlreadyInitialized(loggerContext)) {
            return;
        }
        loggerContext.getConfiguration().removeFilter(FILTER);
        super.initialize(initializationContext, configLocation, logFile);
        markAsInitialized(loggerContext);
    }
    
    // AbstractLoggingSystem.initialize
    @Override
    public void initialize(LoggingInitializationContext initializationContext,
            String configLocation, LogFile logFile) {
        if (StringUtils.hasLength(configLocation)) {
            initializeWithSpecificConfig(initializationContext, configLocation, logFile);
            return;
        }
        initializeWithConventions(initializationContext, logFile);
    }   
    
    // AbstractLoggingSystem.initializeWithSpecificConfig
    private void initializeWithSpecificConfig(
            LoggingInitializationContext initializationContext, String configLocation,
            LogFile logFile) {
        configLocation = SystemPropertyUtils.resolvePlaceholders(configLocation);
        loadConfiguration(initializationContext, configLocation, logFile);
    }
    
    @Override
    protected void loadConfiguration(LoggingInitializationContext initializationContext,
            String location, LogFile logFile) {
        super.loadConfiguration(initializationContext, location, logFile);
        loadConfiguration(location, logFile);
    }   
    
    protected void loadConfiguration(String location, LogFile logFile) {
        Assert.notNull(location, "Location must not be null");
        try {
            LoggerContext ctx = getLoggerContext();
            URL url = ResourceUtils.getURL(location);
            ConfigurationSource source = getConfigurationSource(url);
            ctx.start(ConfigurationFactory.getInstance().getConfiguration(ctx, source));
        }
        catch (Exception ex) {
            throw new IllegalStateException(
                    "Could not initialize Log4J2 logging from " + location, ex);
        }
    }

这一段可能看着方法比较多，但是实际上就是为了一些层次结构带来的，比如和具体日志框架无关的都在抽象类，只有涉及到具体日志框架的才会在子类里，基本流程比较清晰：

把刚才Deny所有日志的Filter给去掉
加载配置文件来进行初始化
LoggerContext里标记一下初始化完毕

这三步都是具体日志框架（Log4J2）的实现。抽象层只负责提供配置文件的路径

简易的输出日志文件机制

LogFile是SpringBoot自己定义的日志输出文件，通过两个参数指定具体的文件：

参数	作用
logging.file	文件名
logging.path	文件路径

Logger的Level调整机制

initializeEarlyLoggingLevel和initializeFinalLoggingLevels这两个方法结合起来看，主要SpringBoot用来调整一些Logger的Level的：

    static {
        LOG_LEVEL_LOGGERS = new LinkedMultiValueMap<LogLevel, String>();
        LOG_LEVEL_LOGGERS.add(LogLevel.DEBUG, "org.springframework.boot");
        LOG_LEVEL_LOGGERS.add(LogLevel.TRACE, "org.springframework");
        LOG_LEVEL_LOGGERS.add(LogLevel.TRACE, "org.apache.tomcat");
        LOG_LEVEL_LOGGERS.add(LogLevel.TRACE, "org.apache.catalina");
        LOG_LEVEL_LOGGERS.add(LogLevel.TRACE, "org.eclipse.jetty");
        LOG_LEVEL_LOGGERS.add(LogLevel.TRACE, "org.hibernate.tool.hbm2ddl");
        LOG_LEVEL_LOGGERS.add(LogLevel.DEBUG, "org.hibernate.SQL");
    }
    
    private void initializeEarlyLoggingLevel(ConfigurableEnvironment environment) {
        if (this.parseArgs && this.springBootLogging == null) {
            if (isSet(environment, "debug")) {
                this.springBootLogging = LogLevel.DEBUG;
            }
            if (isSet(environment, "trace")) {
                this.springBootLogging = LogLevel.TRACE;
            }
        }
    }   
    
    private void initializeFinalLoggingLevels(ConfigurableEnvironment environment,
            LoggingSystem system) {
        if (this.springBootLogging != null) {
            initializeLogLevel(system, this.springBootLogging);
        }
        // 调整自定义的Logger Level
        setLogLevels(system, environment);
    }

上面代码的最后一行setLogLevels，这个是用来自定义调整Logger Level的：

    protected void setLogLevels(LoggingSystem system, Environment environment) {
        Map<String, Object> levels = new RelaxedPropertyResolver(environment)
                .getSubProperties("logging.level.");
        boolean rootProcessed = false;
        for (Entry<String, Object> entry : levels.entrySet()) {
            String name = entry.getKey();
            if (name.equalsIgnoreCase(LoggingSystem.ROOT_LOGGER_NAME)) {
                if (rootProcessed) {
                    continue;
                }
                name = null;
                rootProcessed = true;
            }
            setLogLevel(system, environment, name, entry.getValue().toString());
        }
    }

这里涉及到三个参数：

参数	作用
debug	设置org.springframework.boot/org.hibernate.SQL这两个Logger的Level为DEBUG
trace	设置org.springframework等七个Logger的Level为Trace
logging.level	指定某个Logger的Level，比如logging.level.org.hibernate=ERROR

按需注册ShutdownHook

    private void registerShutdownHookIfNecessary(Environment environment,
            LoggingSystem loggingSystem) {
        boolean registerShutdownHook = new RelaxedPropertyResolver(environment)
                .getProperty(REGISTER_SHUTDOWN_HOOK_PROPERTY, Boolean.class, false);
        if (registerShutdownHook) {
            Runnable shutdownHandler = loggingSystem.getShutdownHandler();
            if (shutdownHandler != null
                    && shutdownHookRegistered.compareAndSet(false, true)) {
                registerShutdownHook(new Thread(shutdownHandler));
            }
        }
    }

这块需要注意下。就是如果ShutdownHook设置不当，可能会造成日志丢失的。

至此，SpringBoot初始化日志系统的源代码分析就结束了。下面再顺带看下另外三个事件

ApplicationPreparedEvent

这个阶段是在application创建并准备完毕后，refresh之前

    private void onApplicationPreparedEvent(ApplicationPreparedEvent event) {
        ConfigurableListableBeanFactory beanFactory = event.getApplicationContext()
                .getBeanFactory();
        if (!beanFactory.containsBean(LOGGING_SYSTEM_BEAN_NAME)) {
            beanFactory.registerSingleton(LOGGING_SYSTEM_BEAN_NAME, this.loggingSystem);
        }
    }

这里只是把LoggingSystem注册到容器中

ContextClosedEvent || ApplicationFailedEvent

这两个阶段分别是容器关闭和SpringBoot启动失败，都需要做一些清理动作，这块就不细看了

    private void onContextClosedEvent() {
        if (this.loggingSystem != null) {
            this.loggingSystem.cleanUp();
        }
    }

    private void onApplicationFailedEvent() {
        if (this.loggingSystem != null) {
            this.loggingSystem.cleanUp();
        }
    }
    
    @Override
    public void cleanUp() {
        super.cleanUp();
        LoggerContext loggerContext = getLoggerContext();
        markAsUninitialized(loggerContext);
        loggerContext.getConfiguration().removeFilter(FILTER);
    }

SpringBoot如何判断选择哪个LoggingSystem

上面的分析是直接拿着Log4J2LoggingSystem就开始了，并没有交代SpringBoot是如何判定用哪个LoggingSystem的，这里回头来看看：

    public static LoggingSystem get(ClassLoader classLoader) {
        String loggingSystem = System.getProperty(SYSTEM_PROPERTY);
        if (StringUtils.hasLength(loggingSystem)) {
            if (NONE.equals(loggingSystem)) {
                return new NoOpLoggingSystem();
            }
            return get(classLoader, loggingSystem);
        }
        for (Map.Entry<String, String> entry : SYSTEMS.entrySet()) {
            if (ClassUtils.isPresent(entry.getKey(), classLoader)) {
                return get(classLoader, entry.getValue());
            }
        }
        throw new IllegalStateException("No suitable logging system located");
    }

如果有通过参数明确指定的，就走参数指定的，其中有一类特殊的NoOpLoggingSystem（啥也不干）
没有指定的话，就根据顺序一次去看下能不能加载到核心类，选择第一个能加载到类的日志框架

看下是怎么个顺序(key是类名，value是对应的日志系统实现类)：

    static {
        Map<String, String> systems = new LinkedHashMap<String, String>();
        systems.put("ch.qos.logback.core.Appender",
                "org.springframework.boot.logging.logback.LogbackLoggingSystem");
        systems.put("org.apache.logging.log4j.core.impl.Log4jContextFactory",
                "org.springframework.boot.logging.log4j2.Log4J2LoggingSystem");
        systems.put("java.util.logging.LogManager",
                "org.springframework.boot.logging.java.JavaLoggingSystem");
        SYSTEMS = Collections.unmodifiableMap(systems);
    }

完整流程图（以Log4J2LoggingSystem为例）

image.png

常见问题

了解了上面的过程之后，我们来看一下日常可能会碰到哪些问题

部分日志丢失

是的，在日志框架初始化之前，理论上日志是打印不出来的。比如在ApplicationStartingEvent和ApplicationEnvironmentPreparedEvent之间需要打印的日志就丢失了

日志框架初始化两次

假设在SpringBoot初始化底层日志框架之前，调用了Logger.xxx之类的方法打印日志，虽然理论上日志是打印不出来，但是却还是触发了底层日志框架的初始化。然后在SpringBoot会再初始化（reconfigure）一次。这块可能在debug代码或者是开了log4j的debug日志的时候会有一些疑惑

最佳实践

解决丢日志的问题

由于集成了分布式配置中心，需要远程读取配置文件，所以在ApplicationStartingEvent和ApplicationEnvironmentPreparedEvent之间需要打印日志，所以需要做一些调整

最简单的想法，是直接不用SpringBoot这一套日志系统的设计，启动参数加上

-Dorg.springframework.boot.logging.LoggingSystem=none

但是这样存在一个问题，因为没有注册SLF4JBridgeHandler，会导致jul框架打印出来的日志丢掉了。那有没有什么好办法呢？自己动手，丰衣足食，我们自己打造一个LoggingSystem：

public class MyLog4j2LoggingSystem extends Slf4JLoggingSystem {

    public MyLog4j2LoggingSystem(ClassLoader classLoader) {
        super(classLoader);
    }

    @Override
    public void initialize(LoggingInitializationContext initializationContext,
            String configLocation, LogFile logFile) {

    }

    @Override
    protected String[] getStandardConfigLocations() {
        return new String[0];
    }

    @Override
    protected void loadDefaults(LoggingInitializationContext initializationContext,
            LogFile logFile) {

    }

    @Override
    public void setLogLevel(String loggerName, LogLevel level) {

    }
}

仅仅只是继承了Slf4JLoggingSystem，其他方法全部留空，这样就能保证jul框架的日志正常打印出来，也能保证启动过程中也不会丢日志

最后编辑于：2019.03.08 21:03:09

人面猴
序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
沈念sama阅读 204,590评论 6赞 478
死咒
序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
沈念sama阅读 86,808评论 2赞 381
救了他两次的神仙让他今天三更去死
文/潘晓璐我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
开封第一讲书人阅读 151,151评论 0赞 337
道士缉凶录：失踪的卖姜人
文/不坏的土叔我叫张陵，是天一观的道长。经常有香客问我，道长，这世上最难降的妖魔是什么？我笑而不...
开封第一讲书人阅读 54,779评论 1赞 277
港岛之恋（遗憾婚礼）
正文为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
茶点故事阅读 63,773评论 5赞 367
恶毒庶女顶嫁案：这布局不是一般人想出来的
文/花漫我一把揭开白布。她就那样静静地躺着，像睡着了一般。火红的嫁衣衬着肌肤如雪。梳的纹丝不乱的头发上，一...
开封第一讲书人阅读 48,656评论 1赞 281
城市分裂传说
那天，我揣着相机与录音，去河边找鬼。笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。我是一名探鬼主播，决...
沈念sama阅读 38,022评论 3赞 398
双鸳鸯连环套：你想象不到人心有多黑
文/苍兰香墨我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
开封第一讲书人阅读 36,678评论 0赞 258
万荣杀人案实录
序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
沈念sama阅读 41,038评论 1赞 299
护林员之死
正文独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋以下内容为张勋视角年9月15日...
茶点故事阅读 35,659评论 2赞 321
白月光启示录
正文我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
茶点故事阅读 37,756评论 1赞 330
活死人
序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
沈念sama阅读 33,411评论 4赞 321
日本核电站爆炸内幕
正文年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
茶点故事阅读 39,005评论 3赞 307
男人毒药：我在死后第九天来索命
文/蒙蒙一、第九天我趴在偏房一处隐蔽的房顶上张望。院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
开封第一讲书人阅读 29,973评论 0赞 19
一桩弑父案，背后竟有这般阴谋
文/苍兰香墨我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。一阵脚步声响...
开封第一讲书人阅读 31,203评论 1赞 260
情欲美人皮
我被黑心中介骗来泰国打工，没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。一个月前我还...
沈念sama阅读 45,053评论 2赞 350
代替公主和亲
正文我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
茶点故事阅读 42,495评论 2赞 343