你好，SLF4J

程序猿杜小头

发布于 2022-12-01 21:45:03

7090

发布于 2022-12-01 21:45:03

文章被收录于专栏：程序猿杜小头

作为 CV 工程师，咱们开发的应用并不总是按预期运行，为了方便排查出潜在的问题，一般会在代码中添加日志记录语句。但在 Java 刚刚问世时，日志记录方式好像除了System.out和System.err之外也没啥别的选择了，主要痛点有：1) 日志无法分级，有些日志纯属 DEBUG，在生产环境是不需要的；2) 日志内容不支持格式化，如 XML、HTML。后来，一位名叫Ceki Gülcü的大神无奈之下发布了大名鼎鼎的log4j。尽管现在 log4j 逐渐退出历史舞台，但在当时却备受 Java 开发人员的喜爱，甚至 JDK 1.4 也是借鉴了 log4j 之后，终于在官方类库中补齐了日志记录这一短板，它就是j.u.l包。

在《阿里 Java 开发手册》中有一条日志规约：【强制】应用中不可直接使用日志系统 (log4j、logback) 中的 API，而应依赖日志门面 (slf4j、jcl) 中的 API 。slf4j (Simple Logging Facade for Java) 同样由 Ceki Gülcü 完成开发，作为一款日志门面，其精心设计了org.slf4j.Logger接口，用于抽象日志记录行为，开发人员只需要与该接口交互即可，这样也就将 Java 应用与具体的日志系统 (jul、log4j、logback 和 log4j2) 解耦开来了。本文重点关注 slf4j 是如何实现 Java 应用与一众日志系统解耦的！

slf4j-1.7.36 于2022年2月份发布，至此，1.X 系列也走到了尽头，后续 slf4j 将基于 2.X 演进下去。目前大多数项目都还在使用 1.X 系列，因此，笔者这里基于 1.7.36 来分析。源码中有十几个模块，笔者以为可以将其核心模块归为三类，如下图所示。

1. binding module

如果当前应用的classpath下不仅有日志系统，而且还有与该日志系统匹配的绑定模块，那么面向 slf4j-api 的日志记录请求最终会被路由到该日志系统中去。

slf4j 共计提供了3个绑定模块，分别是 slf4j-jdk14、slf4j-log4j12 和 slf4j-jcl。难道没有为logback和log4j2提供绑定模块吗？这俩可是当前主流的日志系统啊！非也，logback 也是 Ceki Gülcü 大佬干出来的，绑定模块直接集成到其 logback-classic 模块了；而 log4j2 的绑定模块位于 log4j2 源码的 log4j-slf4j-impl 模块内。

我们一般通过org.slf4j.LoggerFactory.getLogger()这种方式来获取实现了org.slf4j.Logger接口的实例，LoggerFactory 主要内容如下：

package org.slf4j;

public final class LoggerFactory {

    static final int UNINITIALIZED = 0;
    static final int ONGOING_INITIALIZATION = 1;
    static final int FAILED_INITIALIZATION = 2;
    static final int SUCCESSFUL_INITIALIZATION = 3;
    static final int NOP_FALLBACK_INITIALIZATION = 4;

    static volatile int INITIALIZATION_STATE = UNINITIALIZED;
    static String STATIC_LOGGER_BINDER_PATH = "org/slf4j/impl/StaticLoggerBinder.class";
    
    private LoggerFactory() {}

    public static Logger getLogger(Class<?> clazz) {
        return getLogger(clazz.getName());
    }

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

    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);
        }
    }

    private final static void performInitialization() {
        bind();
    }

    private final static void bind() {
        try {
            Set<URL> staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
            if(staticLoggerBinderPathSet.size() > 1) {
                Util.report("Class path contains multiple SLF4J bindings.");
                for (URL path : staticLoggerBinderPathSet) {
                    Util.report("Found binding in [" + path + "]");
                }
            }
            // the next line does the binding
            StaticLoggerBinder.getSingleton();
            INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
            if (staticLoggerBinderPathSet != null && staticLoggerBinderPathSet.size() > 1) {
                Util.report("Actual binding is of type [" + StaticLoggerBinder.getSingleton().getLoggerFactoryClassStr() + "]");
            }
        } catch (NoClassDefFoundError ncde) {
            String msg = ncde.getMessage();
            if (msg.contains("org/slf4j/impl/StaticLoggerBinder") || msg.contains("org.slf4j.impl.StaticLoggerBinder")) {
                INITIALIZATION_STATE = NOP_FALLBACK_INITIALIZATION;
                Util.report("Failed to load class \"org.slf4j.impl.StaticLoggerBinder\".");
                Util.report("Defaulting to no-operation (NOP) logger implementation");
            } else {
                INITIALIZATION_STATE = FAILED_INITIALIZATION;
                Util.report("Failed to instantiate SLF4J LoggerFactory", 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) {
            INITIALIZATION_STATE = FAILED_INITIALIZATION;
            Util.report("Failed to instantiate SLF4J LoggerFactory", e);
            throw new IllegalStateException("Unexpected initialization failure", e);
        }
    }

    static Set<URL> findPossibleStaticLoggerBinderPathSet() {
        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;
    }
}

可见，LoggerFactory 中维护了一个名 INITIALIZATION_STATE 的类变量，用来标识其是否已初始化。初始化逻辑由performInitialization()方法来承载，具体是执行bind()方法内的绑定逻辑。在 bind() 方法内，首先会在当前应用的classpath下搜寻org/slf4j/impl/StaticLoggerBinder.class资源，如果存在多个绑定模块，staticLoggerBinderPathSet 这一 Set<URL> 类型的局部变量中肯定是会有多个元素的；然后进行真正的绑定操作，即StaticLoggerBinder.getSingleton()。细心点的同学应该能发现，在 slf4j-api 和一众绑定模块中，均含有org/slf4j/impl/StaticLoggerBinder.java，那么如何确保一定是绑定模块中的StaticLoggerBinder脱颖而出呢？slf4j-api 模块在打包的时候会排除掉该 Class 文件。另外，StaticLoggerBinder.getSingleton() 这一行代码究竟有何深意呢？毕竟 getSingleton() 方法返回的 StaticLoggerBinder 实例并没有在 bind() 方法内使用。这是为了唤醒 JVM 去主动加载 StaticLoggerBinder，JVM 并不会一次性将所有 Class 文件加载到内存中，而是基于一种延迟加载策略。当 StaticLoggerBinder 调用其 getSingleton() 这一静态方法时，JVM 便会执行 StaticLoggerBinder 中的<clinit>()方法，<clinit>() 方法并不是咱们在 Java 代码中直接编写的方法，而是由编译器自动收集类中静态变量（不包含由 final 关键字修饰的静态常量）的赋值语句和静态初始化代码块合并而产生的；而执行 <clinit>() 方法的过程恰恰对应着类的初始化，初始化是类加载过程的最后一个阶段，必须先执行完加载和连接这俩阶段才行，进而针对 StaticLoggerBinder 类加载的三个阶段也就完成了，使得绑定模块中的 StaticLoggerBinder 成为可以被 JVM 直接使用的 Java 类型，这正是类加载机制的一个典型应用场景，即通过类加载机制来满足灵活的可插拔需求，也许这才是这一行代码背后的深意吧。注意：如果当前应用的classpath下有多个绑定模块，那么 JVM 究竟加载哪一个绑定模块中的 StaticLoggerBinder 呢？这就取决于类加载的顺序了！

下面以 slf4j-jdk14 这一绑定模块为例，分析下该模块提供的 StaticLoggerBinder。如下所示：

package org.slf4j.impl;

import org.slf4j.ILoggerFactory;
import org.slf4j.LoggerFactory;
import org.slf4j.spi.LoggerFactoryBinder;

public class StaticLoggerBinder implements LoggerFactoryBinder {

    private static final StaticLoggerBinder SINGLETON = new StaticLoggerBinder();

    public static final StaticLoggerBinder getSingleton() {
        return SINGLETON;
    }

    private static final String loggerFactoryClassStr = org.slf4j.impl.JDK14LoggerFactory.class.getName();

    private final ILoggerFactory loggerFactory;

    private StaticLoggerBinder() {
        loggerFactory = new org.slf4j.impl.JDK14LoggerFactory();
    }

    public ILoggerFactory getLoggerFactory() {
        return loggerFactory;
    }

    public String getLoggerFactoryClassStr() {
        return loggerFactoryClassStr;
    }
}

从上述内容来看，slf4j-jdk14 中 StaticLoggerBinder 实现了 slf4j-api 中LoggerFactoryBinder接口的两个方法，分别是：getLoggerFactory()和getLoggerFactoryClassStr()。记住，每一个绑定模块中的 StaticLoggerBinder 总是会实现 LoggerFactoryBinder 接口。getLoggerFactory() 方法返回的是JDK14LoggerFactory，JDK14LoggerFactory 是绑定模块 slf4j-jdk14 提供的，其实现了 slf4j-api 中的ILoggerFactory接口，具体如下。

public class JDK14LoggerFactory implements ILoggerFactory {

    ConcurrentMap<String, Logger> loggerMap;

    public JDK14LoggerFactory() {
        loggerMap = new ConcurrentHashMap<String, Logger>();
        // ensure jul initialization
        java.util.logging.Logger.getLogger("");
    }

    public Logger getLogger(String name) {
        // the root logger is called "" in JUL
        if (name.equalsIgnoreCase(Logger.ROOT_LOGGER_NAME)) {
            name = "";
        }

        Logger slf4jLogger = loggerMap.get(name);
        if (slf4jLogger != null)
            return slf4jLogger;
        else {
            java.util.logging.Logger julLogger = java.util.logging.Logger.getLogger(name);
            Logger newInstance = new JDK14LoggerAdapter(julLogger);
            Logger oldInstance = loggerMap.putIfAbsent(name, newInstance);
            return oldInstance == null ? newInstance : oldInstance;
        }
    }
}

原来，绑定模块 slf4j-jdk14 针对 JDK 日志系统的java.util.logging.Logger进行了适配，这个适配器就是JDK14LoggerAdapter，其核心内容如下。

public final class JDK14LoggerAdapter implements Logger {
    transient final java.util.logging.Logger logger;

    JDK14LoggerAdapter(java.util.logging.Logger logger) {
        this.logger = logger;
    }

    public void trace(String format, Object arg) {
        if (logger.isLoggable(Level.FINEST)) {
            FormattingTuple ft = MessageFormatter.format(format, arg);
            log(SELF, Level.FINEST, ft.getMessage(), ft.getThrowable());
        }
    }

    public void debug(String format, Object arg) {
        if (logger.isLoggable(Level.FINE)) {
            FormattingTuple ft = MessageFormatter.format(format, arg);
            log(SELF, Level.FINE, ft.getMessage(), ft.getThrowable());
        }
    }

    public void info(String format, Object arg) {
        if (logger.isLoggable(Level.INFO)) {
            FormattingTuple ft = MessageFormatter.format(format, arg);
            log(SELF, Level.INFO, ft.getMessage(), ft.getThrowable());
        }
    }

    public void warn(String format, Object arg) {
        if (logger.isLoggable(Level.WARNING)) {
            FormattingTuple ft = MessageFormatter.format(format, arg);
            log(SELF, Level.WARNING, ft.getMessage(), ft.getThrowable());
        }
    }

    public void error(String format, Object arg) {
        if (logger.isLoggable(Level.SEVERE)) {
            FormattingTuple ft = MessageFormatter.format(format, arg);
            log(SELF, Level.SEVERE, ft.getMessage(), ft.getThrowable());
        }
    }

    private void log(String callerFQCN, Level level, String msg, Throwable t) {
        LogRecord record = new LogRecord(level, msg);
        record.setLoggerName(getName());
        record.setThrown(t);
        fillCallerData(callerFQCN, record);
        logger.log(record);
    }
}

2. bridge module

如果你开发了一个组件，而且希望上层应用直接通过该组件的 GAV 信息来引入，那么在你这个组件中建议使用日志门面来记录日志，但往往事与愿违，很多开发者还是直接选择具体的日志系统来记录日志，这就有点不规范了。想象一下，如果上层应用使用的日志系统是 logback，而你的组件选用的日志系统却是 log4j，为了将整个应用的日志系统拉齐为 logback，此时你可以用 slf4j 提供的针对 log4j 的桥接模块去替换 log4j 依赖，这样你就不用修改任何代码。从这个例子中，大家可能猜到了桥接模块的作用，就是将面向特定日志系统的日志记录请求路由到 slf4j-api 中去。但有一点需要注意，针对同一款日志系统的绑定模块不能与桥接模块同时存在于当前应用的classpath中，否则会造成死循环！

slf4j 共计提供了3个桥接模块，分别是 jul-to-slf4j、log4j-over-slf4j 和 jcl-over-slf4j。难道也没有为 logback 和 log4j2 提供桥接模块吗？笔者还真的没找到针对 logback 的桥接模块，这也许是大神的自信吧；而 log4j2 的桥接模块位于 log4j2 源码的 log4j-to-slf4j 模块内。

针对 jul 日志系统的桥接模块比较简单，就一个SLF4JBridgeHandler类文件，因而这里选择 jul-to-slf4j 来简单分析下。主要内容有：

package org.slf4j.bridge;

public class SLF4JBridgeHandler extends Handler {
    private static final int TRACE_LEVEL_THRESHOLD = Level.FINEST.intValue();
    private static final int DEBUG_LEVEL_THRESHOLD = Level.FINE.intValue();
    private static final int INFO_LEVEL_THRESHOLD = Level.INFO.intValue();
    private static final int WARN_LEVEL_THRESHOLD = Level.WARNING.intValue();
    
    public static void install() {
        java.util.logging.Logger rootLogger = LogManager.getLogManager().getLogger("");
        rootLogger.addHandler(new org.slf4j.bridge.SLF4JBridgeHandler());
    }
    
    public static void uninstall() throws SecurityException {
        java.util.logging.Logger rootLogger = LogManager.getLogManager().getLogger("");
        Handler[] handlers = rootLogger.getHandlers();
        for (int i = 0; i < handlers.length; i++) {
            if (handlers[i] instanceof org.slf4j.bridge.SLF4JBridgeHandler) {
                rootLogger.removeHandler(handlers[i]);
            }
        }
    }

    public void publish(LogRecord record) {
        Logger slf4jLogger = getSLF4JLogger(record);
        callPlainSLF4JLogger(slf4jLogger, record);
    }
    
    public void close() {}
    
    public void flush() {}
    
    protected Logger getSLF4JLogger(LogRecord record) {
        return LoggerFactory.getLogger(record.getLoggerName());
    }

    protected void callPlainSLF4JLogger(Logger slf4jLogger, LogRecord record) {
        String i18nMessage = getMessageI18N(record);
        int julLevelValue = record.getLevel().intValue();
        if (julLevelValue <= TRACE_LEVEL_THRESHOLD) {
            slf4jLogger.trace(i18nMessage, record.getThrown());
        } else if (julLevelValue <= DEBUG_LEVEL_THRESHOLD) {
            slf4jLogger.debug(i18nMessage, record.getThrown());
        } else if (julLevelValue <= INFO_LEVEL_THRESHOLD) {
            slf4jLogger.info(i18nMessage, record.getThrown());
        } else if (julLevelValue <= WARN_LEVEL_THRESHOLD) {
            slf4jLogger.warn(i18nMessage, record.getThrown());
        } else {
            slf4jLogger.error(i18nMessage, record.getThrown());
        }
    }
}

要想读懂上述源码内容，需要简单铺垫一下 jul 的相关知识。在 jul 中，有几个概念比较重要，LogManager用于读取日志配置文件、创建和维护 Logger 实例；Handler类似于 log4j 中的Appender，它决定了日志记录的输出方向，比如：Console、File 和 Memory 等，一个 Logger 实例可以持有多个 Handler；Formatter用于格式化日志记录，它决定了日志记录的样式。Logger通常是有名称的，一般是包的名称；每一个 Logger 实例会根据命名空间跟踪其父级 Logger，子 Logger 可以继承父 Logger 中的LogLevel和 Handler 等资源；根 (Root) Logger 的名称为""。

SLF4JBridgeHandler 继承了 jul 的 Handler 接口，重写了其publish()方法，主要逻辑就是委派 slf4j 来记录请求。现在自定义的 Handler 有了，还必须将其添加到 jul 的根 (Root) Logger 中去，这也恰是上述install()方法中的内容。

3. 总结

其实之所以写这篇文章，是看了美团一篇技术文章《日志级别动态调整——小工具解决大问题》，原文把绑定模块说成了桥接模块，这应该是一处错误的表述。另外，作者分享了一个真实案例，很值得我们警惕：发配送服务化项目由于间接依赖，引入了 logback 日志系统。在项目启动加载时，slf4j 动态绑定到 logback 上，但是由于发配送项目使用的 log4j，并未配置 logback.xml文件，导致在打印日志时，logback 无法匹配到具体的日志配置，从而为项目自动创建了一个日志级别为 DEBUG 的 Root Logger，所有的 Logger 以该级别打印输出，导致发配送服务化项目在中午左右高峰期，短时间内打印过多的系统日志，引起系统负载飙高，造成服务化宕机，损失非常严重。