java日志框架之logback初探

Posted 2021-04-24 一个懒惰的程序员

一，背景

相信做java开发的同学大部分都用过或者接触过logback，没用过logback那至少也用过log4j，但不知道多少同学跟小编曾经一样，仅仅是网上找来一些配置引入到项目使用而不报错就完事，而没有关心logback具体的实现细节，基于此小编准备系统学习一下logback，整个内容大概在5,6篇文章的样子，一个是为了自己学习logback过程中的总结，另一个也希望对想学logback实现原理的同学有一点借鉴

二，logback介绍

Logback是由log4j创始人设计的又一个开源日志组件。logback当前分成三个模块：logback-core，logback- classic和logback-access。logback-core是其它两个模块的基础模块。logback-classic是log4j的一个改良版本。此外logback-classic完整实现SLF4J API使你可以很方便地更换成其它日志系统如log4j或JDK14 Logging。logback-access访问模块与Servlet容器集成提供通过Http来访问日志的功能。 Logback是要与SLF4J结合起来用两个组件的官方网站如下：

logback的官方网站：http://logback.qos.ch 

SLF4J的官方网站：http://www.slf4j.org

三，logback日志级别

Logback日志级别主要有7个, 分别为OFF>ERROR>WARN>INFO>DEBUG>TRACE>ALL

定义在ch.qos.logback.classic.Level类中可以找到, 一般常用的有ERROR，WARN，INFO，DEBUG这4个

四，logback之打印hello world

在使用logback前需要先在pom文件中加入如下配置：

<dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-core</artifactId>
        <version>1.2.3</version>
</dependency>

<dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-classic</artifactId>
        <version>1.2.3</version>
</dependency>

<dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>
        <version>1.7.25</version>
</dependency>

测试logback如下：

public class DemoHelloword {

    public static void main(String[] args) {
        Logger logger = LoggerFactory.getLogger(DemoHelloword.class);
        logger.error("Hello world.");
        logger.debug("Hello world.");
        logger.warn("Hello world.");
        logger.info("Hello world.");

    }
}

运行在控制台将会看到如下输出：

18:13:17.391 [main] ERROR com.zhiliao.demo.DemoHelloword - Hello world.
18:13:17.395 [main] DEBUG com.zhiliao.demo.DemoHelloword - Hello world.
18:13:17.396 [main] WARN com.zhiliao.demo.DemoHelloword - Hello world.
18:13:17.396 [main] INFO com.zhiliao.demo.DemoHelloword - Hello world.

怎么样4种级别的日志是不是都打印出来了，是不是超级简单，接下来让我们来看一个稍微复杂一点的，假设我们不想看到对应的debug日志级别的日志

我们先在src/resourse目录下边新增一个logback.xml的配置文件如下：

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <!-- encoders are assigned the type ch.qos.logback.classic.encoder.PatternLayoutEncoder 
            by default -->
        <encoder>
            <pattern>%d{YYYY-MM-dd HH:mm:ss.SSS} %contextName [%thread] %-5level %logger{36} - %msg%n
            </pattern>
        </encoder>
    </appender>

    <root level="info">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

根据以上日志级别对应的OFF>ERROR>WARN>INFO>DEBUG>TRACE>ALL执行顺序，我们必须把对应的级别设置为INFO以上debug日志才不会打印，那么这边我们就在最顶层root级别设置日志级别为info,运行结果如下：

2018-08-12 18:06:57,123 [main] [ERROR] [com.zhiliao.demo.DemoHelloword:16] - Hello world.
2018-08-12 18:06:57,127 [main] [WARN] [com.zhiliao.demo.DemoHelloword:18] - Hello world.
2018-08-12 18:06:57,127 [main] [INFO] [com.zhiliao.demo.DemoHelloword:19] - Hello world.

五，logback之打印hello world原理分析

让我们带着两个小问题来分析吧：

1. 为什么在我们只引入了对应的logback包就可以直接使用logback打印，并且还打印出了对应的日志格式

2. 为什么在src/resourse目录下边新增一个logback.xml配置文件就可以控制logback的日志级别等

让我们从程序的入口LoggerFactory.getLogger(DemoHelloword.class)进入到getLogger方法，如下：

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

继续跟进到getILoggerFactory方法如下：

 public static ILoggerFactory getILoggerFactory() {
         #初始化会先进入if条件中
        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");
}

一直进入我们可以发现有bind方法如下：

 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方法。。。。。
}

注意StaticLoggerBinder.getSingleton()这行代码返回的是StaticLoggerBinder实例，其中有一个初始化方法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);
        }
}

进入到autoConfig方法如下：

public void autoConfig() throws JoranException {
        StatusListenerConfigHelper.installIfAsked(loggerContext);
        # 问题2 答案在此
        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 {
                # 问题1 答案在此
                BasicConfigurator basicConfigurator = new BasicConfigurator();
                basicConfigurator.setContext(loggerContext);
                basicConfigurator.configure(loggerContext);
            }
        }
}

重点来了，大家注意进入findURLOfDefaultConfigurationFile方法如下：

public URL findURLOfDefaultConfigurationFile(boolean updateStatus) {
        ClassLoader myClassLoader = Loader.getClassLoaderOfObject(this);
        # 先从系统变量中找出logback.configurationFile的值加载
        URL url = findConfigFileURLFromSystemProperties(myClassLoader, updateStatus);
        if (url != null) {
            return url;
        }
        # 系统变量中会找到对应配置则去资源路径下找logback-test.xml配置
        url = getResource(TEST_AUTOCONFIG_FILE, myClassLoader, updateStatus);
        if (url != null) {
            return url;
        }
        # logback-test.xml配置没找到继续找logback.groovy配置
        url = getResource(GROOVY_AUTOCONFIG_FILE, myClassLoader, updateStatus);
        if (url != null) {
            return url;
        }
        # logback.groovy配置未找到则最终找logback.xml配置
        return getResource(AUTOCONFIG_FILE, myClassLoader, updateStatus);
}

代码中注释已经写的比较清楚了，到这里问题2想必你已经知道原因了吧，仔细的同学肯定已经发现了在以上autoConfig方法中我已经标明对应的答案地方，这里我们跟进去问题1答案BasicConfigurator的configure方法中如下：

public void configure(LoggerContext lc) {
        addInfo("Setting up default configuration.");

        ConsoleAppender<ILoggingEvent> ca = new ConsoleAppender<ILoggingEvent>();
        ca.setContext(lc);
        ca.setName("console");
        LayoutWrappingEncoder<ILoggingEvent> encoder = new LayoutWrappingEncoder<ILoggingEvent>();
        encoder.setContext(lc);

       // 格式化地方
        // same as 
        // PatternLayout layout = new PatternLayout();
        // layout.setPattern("%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n");
        TTLLLayout layout = new TTLLLayout();

        layout.setContext(lc);
        layout.start();
        encoder.setLayout(layout);

        ca.setEncoder(encoder);
        ca.start();

        Logger rootLogger = lc.getLogger(Logger.ROOT_LOGGER_NAME);
        rootLogger.addAppender(ca);
}

从中我们可以很清楚的看到默认日志格式化用的是TTLLLayout中的doLayout方法如下：

public String doLayout(ILoggingEvent event) {
        if (!isStarted()) {
            return CoreConstants.EMPTY_STRING;
        }
        StringBuilder sb = new StringBuilder();

        long timestamp = event.getTimeStamp();

        sb.append(cachingDateFormatter.format(timestamp));
        sb.append(" [");
        sb.append(event.getThreadName());
        sb.append("] ");
        sb.append(event.getLevel().toString());
        sb.append(" ");
        sb.append(event.getLoggerName());
        sb.append(" - ");
        sb.append(event.getFormattedMessage());
        sb.append(CoreConstants.LINE_SEPARATOR);
        IThrowableProxy tp = event.getThrowableProxy();
        if (tp != null) {
            String stackTrace = tpc.convert(event);
            sb.append(stackTrace);
        }
        return sb.toString();
 }

到此我们问题1和问题2就都已经搞清楚，也对logback简单的使用有了一个了解了并且做到了知其然也知其所以然了，今天logback之初探就到此了，更多logback高级用户敬请期待......