日志组件slf4j的使用和源码分析

slf4j全称是Simple Logging Facade for Java。facade是一种设计模式。

slf4j 是一个抽象程度更高的日志组件,本身并不提供实际的日志功能。实际的日志功能是通过log4j等日志组件实现,而使用者只需要关心 slf4j 给出的API。

示例代码: https://github.com/letiantian/demo/tree/master/slf4j

结合Log4j的使用示例 - 示例1

使用 IDEA 创建 gradle项目,我用的gradle版本是4.1。

在 build.gradle 的 dependencies 中增加依赖:

// https://mvnrepository.com/artifact/org.slf4j/slf4j-api
compile group: 'org.slf4j', name: 'slf4j-api', version: '1.7.25'

// https://mvnrepository.com/artifact/org.slf4j/slf4j-log4j12
compile group: 'org.slf4j', name: 'slf4j-log4j12', version: '1.7.25'

// https://mvnrepository.com/artifact/log4j/log4j
compile group: 'log4j', name: 'log4j', version: '1.2.17'
  • slf4j-api提供了slf4j的抽象接口,我们作为使用者,只需要关心它提供的API就行。
  • slf4j-log4j12是slf4j与log4j的桥接组件。
  • log4j是我们常见的log4j日志组件。

src/main/java目录下创建类Example01.java,内容如下:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Example01 {

    public static void main(String[] args) {
        Logger logger = LoggerFactory.getLogger(Example01.class);
        logger.info("Hello {}", "World");
    }
}

logger.info("Hello {}", "World");的作用是打出info级别的日志内容Hello World。是的,我们不必写成logger.info("Hello %s", "World"); 或者logger.info("Hello " + "World");,一切变得不用想太多了。

运行 Example01,输出:

log4j:WARN No appenders could be found for logger (Example01).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.

是的,没有输出我们想要的内容,反而报了警告。这是因为我们没有配置log4j。

src/main/resources目录中创建文件log4j.properties,内容如下:

log4j.rootLogger=INFO, stdout
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%5p [%t] - %m%n

再次运行 Example01,将会输出:

 INFO [main] - Hello World

结合Log4j的使用示例 - 示例2

log4j有一个MDC(Mapped Diagnostic Context)、NDC(Nested Diagnostic Context)机制,这个机制用于打印一些线程粒度上下文信息,但又不需要每次logger.info时把上下文信息填进去。

slf4j提供了对MDC的封装。

有什么使用场景呢?比如我们写了一个web服务器,客户端的每一次请求一般都是放在一个线程中处理的。如果我们想在日志中加入客户端的IP信息,就可以用到MDC。

首先修改log4j.properties中的log4j.appender.stdout.layout.ConversionPattern,在值中加入%X{IP}

log4j.rootLogger=INFO, stdout
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%5p [%t] %X{IP} - %m%n

创建新的Java类Example02:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

public class Example02 {

    public static void main(String[] args) {
        Logger logger = LoggerFactory.getLogger(Example01.class);
        MDC.put("IP", "123.123.123.123");
        logger.info("Hello {}", "World");
    }
}

运行结果:

 INFO [main] 123.123.123.123 - Hello World

Example01 也能正常运行,只不过没有IP信息而已。

结合Log4j的使用示例 - 示例3

slf4j自带了一个很好用的formatter,{}会被替换成对应的变量值。那么,如何转义{}呢 ?

创建新的Java类Example03:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

public class Example03 {

    public static void main(String[] args) {
        Logger logger = LoggerFactory.getLogger(Example03.class);

        MDC.put("IP", "123.123.123.123");
        logger.info("Hello {}", "World");
        logger.info("Hello {} {}", "World");
        logger.info("Hello {} \\{}", "World");
        logger.info("Hello {} \\{} {}", "World");
        logger.info("Hello {} \\{} {}", "World", "HI");
    }
}

运行后输出:

 INFO [main] 123.123.123.123 - Hello World
 INFO [main] 123.123.123.123 - Hello World {}
 INFO [main] 123.123.123.123 - Hello World \{}
 INFO [main] 123.123.123.123 - Hello World \{} {}
 INFO [main] 123.123.123.123 - Hello World {} HI

我们把info的第一个参数称为format字符串,剩下的参数叫做参数列表。
可以总结下:

  1. 如果format字符串中的{},在参数列表找不到对应的参数。那么{}会被打印出来。
  2. 如果format字符串中\\{}在两个{}之间,如果这两个{}能在参数列表中找到对应的参数,则\\{}会被输出为{}

结合slf4j-simple的使用示例

slf4j-simple是slf4j系列自带的一个日志实现,可以不用配置,默认会把日志打印到终端。

使用 IDEA 新创建一个 gradle 项目。
build.gradle中添加依赖:

// https://mvnrepository.com/artifact/org.slf4j/slf4j-api
compile group: 'org.slf4j', name: 'slf4j-api', version: '1.7.25'
// https://mvnrepository.com/artifact/org.slf4j/slf4j-simple
compile group: 'org.slf4j', name: 'slf4j-simple', version: '1.7.25'

编写类 Example01,内容如下:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Example01 {
    public static void main(String[] args) {
        Logger logger = LoggerFactory.getLogger(Example01.class);
        logger.info("Hello {}", "World");
    }
}

运行后输出:

[main] INFO Example01 - Hello World

如果要配置slf4j-simple,可以参考下这篇文章: How to configure slf4j-simple

剖析:slf4j如何找到log4j?

我们一点点翻代码。

首先:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Example01 {

    public static void main(String[] args) {
        Logger logger = LoggerFactory.getLogger(Example01.class);
        logger.info("Hello {}", "World");
    }
}

LoggerFactory.getLogger的主要实现:

package org.slf4j;
public final class LoggerFactory {
    // ... 省略

    public static Logger getLogger(Class<?> clazz) {
        Logger logger = getLogger(clazz.getName());
        // ... 省略
        return logger;
    }

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

   // ... 省略
}

getLoggerFactory 是如何实现的?

public final class LoggerFactory {
    // ... 省略
    public static ILoggerFactory getILoggerFactory() {
        // ... 省略部分代码
        performInitialization();
        return StaticLoggerBinder.getSingleton().getLoggerFactory();
    }
    // ... 省略
}

performInitialization()的主要特性是调用 bind() 方法。

我们直接看bind()的实现:

public final class LoggerFactory {
    // ... 省略
    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();
        } catch (Exception e) {
            failedBinding(e);
            throw new IllegalStateException("Unexpected initialization failure", e);
        }
    }
    // ... 省略
}

findPossibleStaticLoggerBinderPathSet()是去找当前classpath下所有的org/slf4j/impl/StaticLoggerBinder.class。如果有多个,则通过reportMultipleBindingAmbiguity发出警告。

是的,classpath下(包括自己的代码)有完全路径重名的类是可以接受的,如果我们代码里要获取这种类的实例,或者已经import进来了,实际使用的类是找到的第一个符合条件的类。所以有时会遇到坑,比如一个项目的jar包的低版本和高本版都在classpath中,我们希望用高版本中特性,但是程序表现一直不符合我们的预期。这时,可能是因为程序实际用的是低版本特性。这种情况下,需要分析依赖关系,禁止掉重复的依赖。防痴呆设计提供了一个简单但很有意思的思路,来防止自己编写的代码库出现这种问题。
当然,一个jar中不会出现完全路径重名的类。

然后,最重要的代码来了:

StaticLoggerBinder.getSingleton();

我们之前介绍过:

  • slf4j-api提供了slf4j的抽象接口,我们作为使用者,只需要关心它提供的API就行。
  • slf4j-log4j12是slf4j与log4j的桥接组件。
  • log4j是我们常见的log4j日志组件。

我们刚才看到的代码都是slf4j-api中的,但是StaticLoggerBinder这个类是 slf4j-log4j12中的。也就是说,每一个slf4j和实际日志组件的桥接组件中都有一个org.slf4j.impl.StaticLoggerBinder 类。

补充: slf4j-api的源码中是有org.slf4j.impl.StaticLoggerBinder类的,不过没被打包到jar中。它的pom.xml中的打包配置,有一个删除操作:<delete dir="target/classes/org/slf4j/impl"/>

下面,我们进入slf4j-log4j12探索。

StaticLoggerBinder.getSingleton().getLoggerFactory()返回的是什么呢?

Log4jLoggerFactory

我们直接去看Log4jLoggerFactorygetLogger方法:

    public Logger getLogger(String name) {
        // `loggerMap`是缓存logger实例。
        Logger slf4jLogger = loggerMap.get(name);
        if (slf4jLogger != null) {
            return slf4jLogger;
        } else {
            org.apache.log4j.Logger log4jLogger;
            if (name.equalsIgnoreCase(Logger.ROOT_LOGGER_NAME))
                log4jLogger = LogManager.getRootLogger();
            else
                log4jLogger = LogManager.getLogger(name);

            Logger newInstance = new Log4jLoggerAdapter(log4jLogger);
            Logger oldInstance = loggerMap.putIfAbsent(name, newInstance);
            return oldInstance == null ? newInstance : oldInstance;
        }
    }

是的,getLogger并没有直接返回log4j的logger,因为不符合log4j的logger没有继承自org.slf4j.Logger,所以用Log4jLoggerAdapter进行了封装。

Adapter是一种设计模式。

剖析:slf4j的 formatter 原理

我们看下logger.info("Hello {}", "World");中的format机制是如何实现的,即{}是如何被替换的。

slf4j-log4j12Log4jLoggerAdapter类info方法内容如下:

public void info(String format, Object... argArray) {
    if (logger.isInfoEnabled()) {
        FormattingTuple ft = MessageFormatter.arrayFormat(format, argArray);
        logger.log(FQCN, Level.INFO, ft.getMessage(), ft.getThrowable());
    }
}

MessageFormatter来自slf4j-api,arrayFormat 方法有多个同名实现,最终调用的是:

final public static FormattingTuple arrayFormat(final String messagePattern, final Object[] argArray, Throwable throwable) {

    if (messagePattern == null) {
        return new FormattingTuple(null, argArray, throwable);
    }

    if (argArray == null) {
        return new FormattingTuple(messagePattern);
    }

    int i = 0;
    int j;
    // use string builder for better multicore performance
    StringBuilder sbuf = new StringBuilder(messagePattern.length() + 50);

    int L;
    for (L = 0; L < argArray.length; L++) {

        j = messagePattern.indexOf(DELIM_STR, i); // DELIM_STR 的值是 "{}"

        if (j == -1) {
            // no more variables
            if (i == 0) { // this is a simple string
                return new FormattingTuple(messagePattern, argArray, throwable);
            } else { // add the tail string which contains no variables and return
                // the result.
                sbuf.append(messagePattern, i, messagePattern.length());
                return new FormattingTuple(sbuf.toString(), argArray, throwable);
            }
        } else {
            if (isEscapedDelimeter(messagePattern, j)) {
                if (!isDoubleEscaped(messagePattern, j)) {
                    L--; // DELIM_START was escaped, thus should not be incremented
                    sbuf.append(messagePattern, i, j - 1);
                    sbuf.append(DELIM_START);  // DELIM_START 的值是 "{"
                    i = j + 1;
                } else {
                    // The escape character preceding the delimiter start is
                    // itself escaped: "abc x:\\{}"
                    // we have to consume one backward slash
                    sbuf.append(messagePattern, i, j - 1);
                    deeplyAppendParameter(sbuf, argArray[L], new HashMap<Object[], Object>());
                    i = j + 2;
                }
            } else {
                // normal case
                sbuf.append(messagePattern, i, j);
                deeplyAppendParameter(sbuf, argArray[L], new HashMap<Object[], Object>());
                i = j + 2;
            }
        }
    }
    // append the characters following the last {} pair.
    sbuf.append(messagePattern, i, messagePattern.length());
    return new FormattingTuple(sbuf.toString(), argArray, throwable);
}

原理就是解析字符串,进行替换。
对照下面几个用例,理解下就行了:

logger.info("Hello {}", "World");
logger.info("Hello {} {}", "World");
logger.info("Hello {} \\{}", "World");
logger.info("Hello {} \\{} {}", "World");
logger.info("Hello {} \\{} {}", "World", "HI");
( 完 )