全面理解Java中日志那点事

  Java的开发过程离不开日志的处理,但是很多时候我们并不清楚日志这个家族之间的事情,有很多的日志组件,我们之前使用的Log4j,后来的logback,再或者Log4j2

这些日志组件之间到底是什么关系,接下来会全面的分析一下,文章内容会比较长,大家也可以根据自己的需求进行跳跃查看。

一、概述

  首先我们先来捋一捋日志到底有几个门派,不要出现问题的时候找错了掌门。

  首先是原生门派Java.util.logging ,顾名思义就是Java原生提供的日志实现,在我们不添加任何依赖的情况下,也可以在项目中记录日志。

  第二个门派是slf4j门派,这个并不是日志的实现,而是一个日志的接口,也就是说如果项目中只依赖了这个,是无法记录日志的,我们还需要依赖日志的具体实现才能真正的开始记录日志,默认的实现是logback。

  第三个门派是commons-logging,这个是Apache提供的一个通用日志接口,虽然内部也提供了一个Simple logger的实现,但是由于提供的功能比较有限,所以commons-logging通常是以日志接口的方式存在,然后搭配第三方日志实现来完成日志的记录。

  这种接口的方式可以让我们的项目中不直接依赖具体的日志实现,方便解耦,这样在必要的时候我们可以直接更换掉第三方的日志组件,而不需要调整代码。

  各个日志门派之间也是有信使的,可以通过不同的适配器来将不同的日志实现达到统一的输出,方便我们对项目日志进行整合。

  在开始聊具体的实现之前,我觉得有必要先整体的聊一下日志的历史,这对于后面我们理解日志会有很多的帮助,因为本人在最开始遇到日志问题的时候就很头疼,甚至连百度都不知道该百些啥,所以我觉得了解一些日志的历史是很有必要的。

  首先是Log4j应该是日志领域里出现最早的一个框架了,它1999年出道,2012年发布最后一个版本,然后在2015年停止维护,风风雨雨这十多年间积累了大量的用户,以至于现在仍然会有很多项目使用的是log4j。因为它太火了后来被apache收入门下,但是log4j的作者加入了apache之后因为理念的不合,最终选择了离开,之后自己开发了SLF4J 和 Logback。

  因为SLF4J优秀的设计理念和性能优势,很快的吸引了大批量的用户,迅速的建立起了自己的社区。然后Logback因为是天生的血缘关系,与SLF4J的无缝对接,同时吸取了Log4j的经验,也是吸引了很多追随者,迅速圈粉。

  爱恨情仇的干戈让apache有些不甘心,默默的憋大招,终于在2014年的时候发布了Log4j2,这里里面吸取了Logback的很多优秀的特性,而且在很多方面的设计也是超过了Logback,不过Log4j2比Logback晚了好几年。所以后面就有很多人在讨论他俩到底谁才是Log4j正统的接班人,有的人说是Log4j2,因为从名字上来,这才是亲儿子。但是有人说是Logback,因为毕竟是同一个作者,当然这东西很难讨论出结果,而作为使用者的我们,只要找到适合我们项目的日志组件就可以了,神仙打架这种事我们就吃吃瓜就好了。

  SLF4J是一个日志接口而不是一个完整的日志框架,它提供了一套日志记录的api ,但是没有提供相应的日志输出。需要配合Log4j,Logback 或者是Java.util.logging(JUL)来完成日志功能。所以从这个角度来看,SLF4J的对手就是Apache的Jakarta Commons Logging(JCL)。这个也是一个日志记录的接口,但是在JCL的内部提供了一个SimpleLog的日志实现,是用来最后兜底使用的。二者最大的区别就是日志服务的绑定机制:

JCL采用的动态绑定机制:

  1. 在进程启动时尝试获取名为"org.apache.commons.logging.Log"的配置属性(可与在commons-logging.properties文件中配置,或使用Java代码进行配置),按配置选取对应的日志输出服务
  2. 如果没有获取到对应配置属性,会尝试在系统参数中寻找名为"org.apache.commons.logging.Log"的参数项
  3. 如果1,2均没有获取到,会在classpath下寻找log4j的相关class,如果找到,则使用log4j作为日志输出服务
  4. 如果没有找到log4j,则尝试使用java.util.logging包作为日志输出服务
  5. 如果上述都失败,则使用SimpleLog作为日志输出服务,即将所有日志输出至控制台标准输出System.err

  JCL的动态绑定机制基于ClassLoader实现,缺点一是效率较低,二是容易引发混乱,在一个复杂甚至混乱的依赖环境下,确定当前正在生效的日志服务是很费力的,特别是在程序开发和设计人员并不理解JCL的机制时,三是最致命的问题:在使用了自定义ClassLoader的程序中,使用JCL会引发各类问题,例如内存泄露、与OSGI冲突等。

而slf4j则简单得多,采用静态绑定机制:

  • slf4j为各类日志输出服务提供了适配库,如slf4j-log4j12,slf4j-simple,slf4j-jdk14等。一个Java工程下只能引入一个slf4j适配库
  • slf4j会加载org.slf4j.impl.StaticLoggerBinder作为输出日志的实现类。这个类在每个适配库中都存在,所以slf4j不需要像JCL一样主动去寻找日志输出实现,自然而然地就能与具体的日志输出实现绑定起来
  • 当需要更换日志输出服务时(比如从logback切换回log4j),只需要替换掉适配库即
所以slf4j不仅对比JCL有性能上的优势,使用slf4j的程序员也不需要去翻找配置文件或追踪启动过程就能够清除明白地了解当前使用的是什么日志输出服务。
 
  当然这只是SLF4J与JCL最主要的区别,其实也是Log4j作者与Apache最大的分歧点,道不同不相为谋吧,除此之外SLF4J还做了一些其他的改进:
  1.强制输出String:传统的日志api都接收Object类型的参数,在程序员不遵守规范时容易引发一些错误,比如我们传入的Object没有覆盖toString,那最终打印出来的就是对象的hashCode
  2.日志模板功能:之前我们记录日志里面肯定会用的到字符串的拼接,那么不管这条日志是否需要被输出,都会进行字符串的拼接,那么就会浪费很多性能。而SLF4J提供了占位符在日志真正需要输出的时候才进行内容的拼接,减少了一些不必要的性能损耗。
 
  理清了日志框架之间的复杂的关系,接下来继续来梳理一下那些让困惑的jar包。
  在项目中我们肯定遇到过各种的jar包依赖,因为名字包含 slf4j-log4j12.jar ,log4j-over-slf4j.jar,jul-to-slf4j.jar,log4j-to-slf4j.jar等等,遇到问题的时候我们不知道该怎么调整,也不知道每个jar包具体是做什么的,那么下面我们就来梳理一下这些jar包
首先我们知道slf4j和jcl都是接口,那么如果需要日志的输出,就需要指定一个日志的实现,就拿slf4j来说,我们需要添加对应的日志实现才能记录日志,这种jar包就叫做适配包:
  • slf4j-log4j12:使用log4j-1.2作为日志输出服务
  • slf4j-jdk14:使用java.util.logging作为日志输出服务
  • slf4j-jcl:使用JCL作为日志输出服务
  • slf4j-simple:日志输出至System.err
  • slf4j-nop:不输出日志
  • log4j-slf4j-impl:使用log4j2作为日志输出服务
这些都是关于slf4j的适配包,添加了对应的依赖,在添加这些适配包,项目就能够正常的运行了。当如如果你选择是的是logback作为日志的实现,就不需要添加任何的适配包,毕竟是同一个作者写的,天生适配。
但是如果我们依赖了一些老版本的类库,里面还是用JCL来记录日志的,那么在项目中如果我们想要使用slf4j来记录日志,那么就需要一些桥接包了,就是把JCL产生的日志,通过SLF4J来输出,完成日志统一管理的目的,代表性的有:
  • log4j-over-slf4j:将使用log4j api输出的日志桥接至slf4j
  • jcl-over-slf4j:将使用JCL api输出的日志桥接至slf4j
  • jul-to-slf4j:将使用java.util.logging输出的日志桥接至slf4j
  • log4j-to-slf4j:将使用log4j2输出的日志桥接至slf4j
slf4j唯独没有提供log4j2的适配库和桥接库,log4j-slf4j-impl和log4j-to-slf4j都是Apache Logging自己开发的,看样子SLF4J的作者和Apache Logging的梁子真的很深啊

二、Java.util.logging(1.8)

  首先我们通过一个demo来看看Java.util.logging(JUL)在项目中是怎么使用的  

import java.util.logging.Logger;

public class JULTest {
    private static String className = JULTest.class.getName();

    public static void main(String[] args) {
        Logger logger = Logger.getLogger(className);
        logger.severe("[severe]除数不能为0.");
        logger.warning("[warning]除数不能为0.");
        logger.info("[info]除数不能为0.");
        logger.config("[config]除数不能为0.");
        logger.fine("[fine]除数不能为0.");
        logger.finer("[finer]除数不能为0.");
        logger.finest("[finest]除数不能为0.");
    }
}

  再看一下控制台的输出

四月 08, 2020 6:03:37 下午 com.example.LogDemo.nativeLog.JULTest main
严重: [severe]除数不能为0.
四月 08, 2020 6:03:37 下午 com.example.LogDemo.nativeLog.JULTest main
警告: [warning]除数不能为0.
四月 08, 2020 6:03:37 下午 com.example.LogDemo.nativeLog.JULTest main
信息: [info]除数不能为0.

  可以看到不需要进行特别的配置,我们就可以在项目中打印我们需要的日志,但是这只是在控制台打印了,这对于企业级的开发是远远不够的,所以我们可以在安装目录中的jre/lib/logging.properties 里面提供了一个默认的日志配置文件,需要时我们可以把这个配置文件添加到项目中,在这里可以对日志的输出进行配置,包括我们常用的保存到日志文件中。

  下面我们来看看配置文件中的一些关键的配置项:

############################################################
#      Default Logging Configuration File
#
# You can use a different file by specifying a filename
# with the java.util.logging.config.file system property.  
# For example java -Djava.util.logging.config.file=myfile
############################################################

############################################################
#      Global properties
############################################################

# "handlers" specifies a comma separated list of log Handler 
# classes.  These handlers will be installed during VM startup.
# Note that these classes must be on the system classpath.
# By default we only configure a ConsoleHandler, which will only
# show messages at the INFO and above levels.
handlers= java.util.logging.ConsoleHandler

# To also add the FileHandler, use the following line instead.
#handlers= java.util.logging.FileHandler, java.util.logging.ConsoleHandler

# Default global logging level.
# This specifies which kinds of events are logged across
# all loggers.  For any given facility this global level
# can be overriden by a facility specific level
# Note that the ConsoleHandler also has a separate level
# setting to limit messages printed to the console.
.level= INFO

############################################################
# Handler specific properties.
# Describes specific configuration info for Handlers.
############################################################

# default file output is in user's home directory.
java.util.logging.FileHandler.pattern = %h/java%u.log
java.util.logging.FileHandler.limit = 50000
java.util.logging.FileHandler.count = 1
java.util.logging.FileHandler.formatter = java.util.logging.XMLFormatter

# Limit the message that are printed on the console to INFO and above.
java.util.logging.ConsoleHandler.level = INFO
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter

# Example to customize the SimpleFormatter output format 
# to print one-line log message like this:
#     <level>: <log message> [<date/time>]
#
# java.util.logging.SimpleFormatter.format=%4$s: %5$s [%1$tc]%n

############################################################
# Facility specific properties.
# Provides extra control for each logger.
############################################################

# For example, set the com.xyz.foo logger to only log SEVERE
# messages:
com.xyz.foo.level = SEVERE 

  总体来看日志项比较简单,而且注释说明也比较清晰,这里主要说明几个配置项:

  handlers :是控制日志的输出Handler,默认的只有一个ConsoleHandler,可以添加多个,比如下面注释中可以添加一个FileHandler,多个handler之间用逗号进行分割

  com.xyz.foo.level = SERVER : 这个是可以针对不同的类进行不同的日志级别的设置

  .level = INFO : 这个配置项要特别说明一下,这个是一个全局的日志级别,但是对于ConsoleHandler是有一个单独的日志级别控制的 -> java.util.logging.ConsoleHandler.level = INFO

  

  上面这些基本上就是JUL的使用,上手非常的简单,下面我们来看一看具体的实现原理。

 

  首先我们先看下JUL这个框架里面几个重要的类,以及其作用:

    1. Logger:对外发布的日志记录器,应用系统可以通过该对象完成日志记录的功能。
    2. Level: 日志的记录级别
    3. LoggingMXBean:接口对象,对外发布的日志管理器
    4. LogRecord:日志信息描述对象
    5. LoggerManager:日志管理器
    6. Filter:日志过滤器,接口对象,在日志被Handler处理前,起过滤作用
    7. Handler:日志处理器,接口对象,决定日志的输出方式
    8. Formatter:日志格式转化器,接口对象,决定日志的输出格式

  接下来我们就按照Demo中的代码首先看看Logger是怎么创建出来的,跟进创建创建过程可以看到虽然我们调用的是 Logger.getLogger() 但是实际Logger的创建是通过LoggerManager来创建的

private static Logger demandLogger(String name, String resourceBundleName, Class<?> caller) {
        LogManager manager = LogManager.getLogManager();
        SecurityManager sm = System.getSecurityManager();
        if (sm != null && !SystemLoggerHelper.disableCallerCheck) {
            if (caller.getClassLoader() == null) {
                return manager.demandSystemLogger(name, resourceBundleName);
            }
        }
        return manager.demandLogger(name, resourceBundleName, caller);
        // ends up calling new Logger(name, resourceBundleName, caller)
        // iff the logger doesn't exist already
}

无论是SystemLogger 还是普通的Logger 都是通过 LogManager 来创建的,所以我们先看看 LogManager 里面是怎么实现的。

首先是LogManager类的注释说明,因为很长这里就不粘贴了,就重点说明几个点:

  1. 是全局单例的对象,我们随时可以通过 LogManager.getLogManager() 来获取到其对象
  2. 管理了一个Logger命名空间的层级关系,所有的Logger都是保存在这个命名空间中的
  3. 管理着全部的KV的配置属性,所有的handler或者logger都可以使用
  4. 是多线程安全的

其他的内容会在源码分析中再做仔细的说明,首先我们看一个LogManager的初始化吧:

    static {
        manager = AccessController.doPrivileged(new PrivilegedAction<LogManager>() {
            @Override
            public LogManager run() {
                LogManager mgr = null;
                String cname = null;
                try {
                    cname = System.getProperty("java.util.logging.manager");
                    if (cname != null) {
                        try {
                            Class<?> clz = ClassLoader.getSystemClassLoader()
                                    .loadClass(cname);
                            mgr = (LogManager) clz.newInstance();
                        } catch (ClassNotFoundException ex) {
                            Class<?> clz = Thread.currentThread()
                                    .getContextClassLoader().loadClass(cname);
                            mgr = (LogManager) clz.newInstance();
                        }
                    }
                } catch (Exception ex) {
                    System.err.println("Could not load Logmanager \"" + cname + "\"");
                    ex.printStackTrace();
                }
                if (mgr == null) {
                    mgr = new LogManager();
                }
                return mgr;

            }
        });
    }

  是通过一个静态代码块完成的初始化,这里我们看到首先是通过系统参数获取一个属性:java.util.logging.manager ,这个属性如果存在就加载这类,完成LogManager的创建,但是我们通过系统变量获取的时候又发现他是空的,那这是因为什么呢?

  我们思考一个问题,就是如果源码中提供的LogManager不能满足我们的应用程序的需求,比如我们需要在LogManager初始化中做一些文件的加载等等,那么考虑到JVM的类加载机制以及在整个JVM中单例的LogManager的要求,我们应该怎么去做呢?这是一个类,所以我们想要拓展只能通过继承的方式,但是我们怎么保证类的加载又不破坏框架呢?

  答案就在这个静态代码块中,这里的系统属性:java.util.logging.manager 就是为了这个场景考虑的,LogManager不管多么强大都不可能满足所有应用场景的需求,所以我们可以自行对其进行拓展,我们可以在项目中继承LogManager这个类,然后在通过启动的命令中或者是其他的方式设置系统参数,告诉JVM我们需要创建一个我们自定义的LogManager类,而不是默认提供的那个了,所以这就是这段代码的作用。 

  这段代码还有一个点需要我们注意一下,就是首先是通过SystemClassLoader尝试进行加载,如果加载不到会通过线程上下文加载器进行加载,就是为了保证我们自定义的类能够被正确的加载,因为当前的LogManager是在rt.jar包下的,这个包是通过引导类加载器加载进来的,而我们自定义的类是在classpath下的,对于引导类加载器是不可见的,所以这是需要重点关注的地方。

  最后如果我们没有设置系统参数,那么就会创建一个默认的LogManager。

  为了处理这种情况以及保证单例模式,我们看一下LogManager的构造方法:

  /**
     * Protected constructor.  This is protected so that container applications
     * (such as J2EE containers) can subclass the object.  It is non-public as
     * it is intended that there only be one LogManager object, whose value is
     * retrieved by calling LogManager.getLogManager.
     */
    protected LogManager() {
        this(checkSubclassPermissions());
    }

  很明确,提供了一个protected 的无参构造方法,如果我们需要进行子类的拓展,可以在构造方法中处理一些我们自己的逻辑,但是又不会破坏框架的完整性。

    /**
     * Returns the global LogManager object.
     * @return the global LogManager object
     */
    public static LogManager getLogManager() {
        if (manager != null) {
            manager.ensureLogManagerInitialized();
        }
        return manager;
    }

  我们在获取Logger的时候,首先获取全局的LogManager对象,这里首先调用了一下 ensureLogManagerInitialized 方法,通过名字我们可以知道,这个方式是确保LogManager已经被完全初始化了,因为LogManager是全局单例的,只有保证其初始化才能保证其正确的运行。

  下面我们来看看这个 ensureLogManagerInitialized 方法里面具体做了什么:

    /**
     * Lazy initialization: if this instance of manager is the global
     * manager then this method will read the initial configuration and
     * add the root logger and global logger by calling addLogger().
     *
     * Note that it is subtly different from what we do in LoggerContext.
     * In LoggerContext we're patching up the logger context tree in order to add
     * the root and global logger *to the context tree*.
     *
     * For this to work, addLogger() must have already have been called
     * once on the LogManager instance for the default logger being
     * added.
     *
     * This is why ensureLogManagerInitialized() needs to be called before
     * any logger is added to any logger context.
     *
     */
    private boolean initializedCalled = false;
    private volatile boolean initializationDone = false;
    final void ensureLogManagerInitialized() {
        final LogManager owner = this;
        if (initializationDone || owner != manager) {
            // we don't want to do this twice, and we don't want to do
            // this on private manager instances.
            return;
        }

        // Maybe another thread has called ensureLogManagerInitialized()
        // before us and is still executing it. If so we will block until
        // the log manager has finished initialized, then acquire the monitor,
        // notice that initializationDone is now true and return.
        // Otherwise - we have come here first! We will acquire the monitor,
        // see that initializationDone is still false, and perform the
        // initialization.
        //
        synchronized(this) {
            // If initializedCalled is true it means that we're already in
            // the process of initializing the LogManager in this thread.
            // There has been a recursive call to ensureLogManagerInitialized().
            final boolean isRecursiveInitialization = (initializedCalled == true);

            assert initializedCalled || !initializationDone
                    : "Initialization can't be done if initialized has not been called!";

            if (isRecursiveInitialization || initializationDone) {
                // If isRecursiveInitialization is true it means that we're
                // already in the process of initializing the LogManager in
                // this thread. There has been a recursive call to
                // ensureLogManagerInitialized(). We should not proceed as
                // it would lead to infinite recursion.
                //
                // If initializationDone is true then it means the manager
                // has finished initializing; just return: we're done.
                return;
            }
            // Calling addLogger below will in turn call requiresDefaultLogger()
            // which will call ensureLogManagerInitialized().
            // We use initializedCalled to break the recursion.
            initializedCalled = true;
            try {
                AccessController.doPrivileged(new PrivilegedAction<Object>() {
                    @Override
                    public Object run() {
                        assert rootLogger == null;
                        assert initializedCalled && !initializationDone;

                        // Read configuration.
                        owner.readPrimordialConfiguration();

                        // Create and retain Logger for the root of the namespace.
                        owner.rootLogger = owner.new RootLogger();
                        owner.addLogger(owner.rootLogger);
                        if (!owner.rootLogger.isLevelInitialized()) {
                            owner.rootLogger.setLevel(defaultLevel);
                        }

                        // Adding the global Logger.
                        // Do not call Logger.getGlobal() here as this might trigger
                        // subtle inter-dependency issues.
                        @SuppressWarnings("deprecation")
                        final Logger global = Logger.global;

                        // Make sure the global logger will be registered in the
                        // global manager
                        owner.addLogger(global);
                        return null;
                    }
                });
            } finally {
                initializationDone = true;
            }
        }
    }

  我们知道在构造方法中,其实我们只是创建了一个manager的对象,并没有做初始化部分的设置,这个方法就是对LogManager进行初始化的

这里有两个变量:initializedCalled (这个初始化的方法是否被调用) ,initializationDone(初始化是否完成),通过这两个变量共同来保被正确的初始化,不会因为多线程的调用而产生异常情况。

  通过代码可以看到通过synchorized关键字来进行的锁操作,然后在方法内部会再次判断两个变量的属性,如果是有其他的线程已经完成了LogManager的初始化,那么当前的线程就会直接返回。

  初始化的部分主要做了三件事:

  1. 读取配置文件
  2. 创建rootLogger,添加到全局命名空间中
  3. 创建global logger ,添加到全局命名空间中

  这里的处理是很巧妙的,虽然读取了配置文件,但是并没有把配置文件中所有的Logger都进行初始化,而是在真正使用的时候才进行初始化,但是这里需要把全局的配置文件读取出来,这样才能在创建单独Logger的时候方便的处理,所以这里只是创建了一个rootLogger和一个global Logger 。

   在这个初始化的方法中还有一个技术点需要大家思考一下,就是为什么只有 initializationDone 变量是 volatile 的呢?我们知道在多线程环境下如果想要用boolean进行状态的标注,一定是要用

volatile进行修饰的,避免线程读取到缓存的脏数据。但是这里为什么initializedCalled不是volatile的呢?

  通过代码我们可以看到两个变量的作用其实是不一样的,initializedCalled在整个逻辑中被用于以下几个判断使用:

  1. 是否为递归调用
  2. 是否调用了初始化方法

  从使用上来看这两个都是在线程内部来判断的是,其实是不涉及多线程之间交互的,但是 initializationDone 变量就不同,我们来看一下这个变量用来做了哪些判断:

  1. 是否初始化完成
  2. 是否调用过初始化方法

  可见这个变量是用来判断LogManager是否被初始化完成的一个重要变量,虽然在代码中我们看到还有那个是否为递归调用的判断,但是在注释中很明显说明了,如果isrecursiveinitialize为真,则意味着我们已经在这个线程中初始化LogManager了。有一个对ensureLogManagerInitialized()的递归调用。我们不应该继续下去,因为它会导致无限递归。如果initializationDone为真,则表示管理器已经完成了初始化,返回:我们完成了。

  可见两个变量虽然都是判断LogManager是否完成了初始化,但是面向的对象是不同的,一个是对于当前线程,一个是面向全局所有准备初始化的线程。

  

  接下来我们看一下默认的构造方法中做了什么操作:  

    private LogManager(Void checked) {

        // Add a shutdown hook to close the global handlers.
        try {
            Runtime.getRuntime().addShutdownHook(new Cleaner());
        } catch (IllegalStateException e) {
            // If the VM is already shutting down,
            // We do not need to register shutdownHook.
        }
    }

  这里主要是一个Hook程序,钩子程序的主要目的就是为了在JVM退出之前,应用程序需要做的一些工作,显然,这对于一个日志框架而言,是有着非常重要的意义。假设应用程序在运行时崩溃,那么造成系统崩溃的相关的日志将会给我们分析问题和解决问题有很大的帮助,在往下的分析中,我们会发现,在我们现在所描述的这种情况下,相关的日志可能还没有输出,系统就已经崩溃了,那么我们在分析问题和解决问题就失去了很多的依据,所以很有必要确保在JVM退出之前,一定要保证系统崩溃的所有日志都已经输出。而这个钩子程序Cleaner巧妙的解决了这个问题。Cleaner的职责在于在JVM崩溃前,将所有Logger对象的Handler对象关闭,这里的关闭其实是讲handler中所有未输出的日志,或者IO的缓冲区输出,从而确保日志的完完全全的输出。

 


 

  上面聊了很多关于LogManager的细节,但是不要忘记我们最初是从怎么获取Logger引发的思考,所以继续我们的梦想出发。

return manager.demandLogger(name, resourceBundleName, caller);

这个是之前的代码,我们可以看到返回的Logger是通过LogManager的demandLogger方法来获得的,跟进去我们继续找

Logger demandLogger(String name, String resourceBundleName, Class<?> caller) {
        Logger result = getLogger(name);
        if (result == null) {
            // only allocate the new logger once
            Logger newLogger = new Logger(name, resourceBundleName, caller, this, false);
            do {
                if (addLogger(newLogger)) {
                    // We successfully added the new Logger that we
                    // created above so return it without refetching.
                    return newLogger;
                }

                // We didn't add the new Logger that we created above
                // because another thread added a Logger with the same
                // name after our null check above and before our call
                // to addLogger(). We have to refetch the Logger because
                // addLogger() returns a boolean instead of the Logger
                // reference itself. However, if the thread that created
                // the other Logger is not holding a strong reference to
                // the other Logger, then it is possible for the other
                // Logger to be GC'ed after we saw it in addLogger() and
                // before we can refetch it. If it has been GC'ed then
                // we'll just loop around and try again.
                result = getLogger(name);
            } while (result == null);
        }
        return result;
    }

  我们先简单的分析一下这个方法,方法本身先通过getLogger方法来尝试获取Logger,那么这个方法里面应该就是LogManager维护的那个Logger映射关系的存储,然后如果获取不到那么会新创建一个Logger,通过前面的分析我们知道在LogManager初始化的时候

只是初始化了rootLogger 和 globalLogger ,对于配置文件中的其他Logger都没有初始化。但是我们打开Logger的构造方法,发现也只是对一些参数进行赋值,那么这么分析一看,对于Logger的初始化(日志级别,handler)都应该是在那个addLogger的方法中配置的了,

那么接下来就带着我们的猜想去验证吧。

  首先是getLogger方法:

public Logger getLogger(String name) {
        return getUserContext().findLogger(name);
}

获取用户的上下文对象,然后调用其findLogger方法,继续跟进

synchronized Logger findLogger(String name) {
            // ensure that this context is properly initialized before
            // looking for loggers.
            ensureInitialized();
            LoggerWeakRef ref = namedLoggers.get(name);
            if (ref == null) {
                return null;
            }
            Logger logger = ref.get();
            if (logger == null) {
                // Hashtable holds stale weak reference
                // to a logger which has been GC-ed.
                ref.dispose();
            }
            return logger;
}

可以看到首先确保我们的LogManager已经正确的初始化了,然后从根命名空间 namedLoggers 中尝试通过名字获取,如果不为空则返回Logger对象。

这个逻辑比较清晰,但是可能细心的同学会问了,那个 namedLoggers 命名空间是什么啊,怎么保存了Logger啊,来喽,它来喽

// LoggerContext maintains the logger namespace per context.
    // The default LogManager implementation has one system context and user
    // context.  The system context is used to maintain the namespace for
    // all system loggers and is queried by the system code.  If a system logger
    // doesn't exist in the user context, it'll also be added to the user context.
    // The user context is queried by the user code and all other loggers are
    // added in the user context.
    class LoggerContext {
        // Table of named Loggers that maps names to Loggers.
        private final Hashtable<String,LoggerWeakRef> namedLoggers = new Hashtable<>();
        // Tree of named Loggers
        private final LogNode root;
        private LoggerContext() {
            this.root = new LogNode(null, this);
        }

这个是我们上面获取的那个 UserContext ,因为太长了,我们先看当下关心的部分,就是这个 namedLoggers 是一个Hashtable,然后我们的Logger对象是封装在 LoggerWeakRef 对象中

这个 LoggerWeakRef 是一个弱引用,就是只要有GC那么不管内存空间是否足够,只要该对象没有强引用,都会被GC清理,就是说如果我们通过getLogger方法获取一个Logger,那么其实有可能上次秒还能获取到,下一秒它就被回收了

这其实是一个保护机制,避免恶意创建大量Logger导致崩溃。

  所以总结一个LogManager保存Logger的逻辑就是:在其内部有一个用户上下文,在上下文对象中有一个Hashtable对象,用于保存已经创建的Logger,但是value是弱引用的,随时可以被GC回收掉

那么如果是一个没有被缓存过的Logger呢,通过代码可以看到会通过Logger的构造方法创建一个Logger对象:

   Logger(String name, String resourceBundleName, Class<?> caller, LogManager manager, boolean isSystemLogger) {
        this.manager = manager;
        this.isSystemLogger = isSystemLogger;
        setupResourceInfo(resourceBundleName, caller);
        this.name = name;
        levelValue = Level.INFO.intValue();
    }

可见在这个构造方法中其实并没有根据配置文件为其设置日志级别和handler,仅仅是赋值了一些变量,所以玄机还在后面,我们继续来看看 addLogger 方法:

  public boolean addLogger(Logger logger) {
        final String name = logger.getName();
        if (name == null) {
            throw new NullPointerException();
        }
        drainLoggerRefQueueBounded();
        LoggerContext cx = getUserContext();
        if (cx.addLocalLogger(logger)) {
            // Do we have a per logger handler too?
            // Note: this will add a 200ms penalty
            loadLoggerHandlers(logger, name, name + ".handlers");
            return true;
        } else {
            return false;
        }
    }

 首先看一下 drainLoggerRefQueueBounded() 方法,从方法名称上可以看到是清理LoggerRefQueue队列边界的,那么LoggerRefQueue是什么呢?我们先点进这个方法看一下:

private final static int MAX_ITERATIONS = 400;
    final void drainLoggerRefQueueBounded() {
        for (int i = 0; i < MAX_ITERATIONS; i++) {
            if (loggerRefQueue == null) {
                // haven't finished loading LogManager yet
                break;
            }

            LoggerWeakRef ref = (LoggerWeakRef) loggerRefQueue.poll();
            if (ref == null) {
                break;
            }
            // a Logger object has been GC'ed so clean it up
            ref.dispose();
        }
}

这个 MAX_ITERATIONS 是通过计算,然后每次执行方法要清理的弱引用对象的数量,这个方法的逻辑比较简单,就是每次循环从 loggerRefQueue 取出一个对象,然后清理掉,注意这里清理的实际是弱引用的对象,而不是实际弱引用中的对象,那个已经在GC的时候被清理掉了。

书归正传,在清理完弱引用对象之后,尝试获取用户的上下文 LoggerContext ,然后将我们之前创建的Logger对象添加到上下文中,所以我们来看一下这个 addLocalLogger 方法 :

        // Add a logger to this context.  This method will only set its level
        // and process parent loggers.  It doesn't set its handlers.
        synchronized boolean addLocalLogger(Logger logger, boolean addDefaultLoggersIfNeeded) {

这段代码有点长,我们一段一段的分析。

首先是在方法的上方有两行注释对这个方法进行了概括性的说明:将Logger对象添加到这个上下文中,这个方法只处理Logger的等级和处理父类Logger的关系,并不处理对应的handler

首先将当前的Logger添加到上下文中,这个比较好理解,就是维护到Hashtable中,然后处理Logger的等级,就是从LogManager之前读取到的配置文件中,为每个Logger设置其应该关心和处理的日志等级,

这里要多说一句的是维护父类的关系,之前我们说过所有的Logger在这里是一个树形结构,所以我们每次添加Logger的时候都要维护对应的树形结构,方便消息父类处理等场景的时候方便寻找Logger使用。

LoggerWeakRef ref = namedLoggers.get(name);
            if (ref != null) {
                if (ref.get() == null) {
                    // It's possible that the Logger was GC'ed after a
                    // drainLoggerRefQueueBounded() call above so allow
                    // a new one to be registered.
                    ref.dispose();
                } else {
                    // We already have a registered logger with the given name.
                    return false;
                }
}

这里是先尝试通过Hashtable中获取对象的Logger的弱引用,如果存在则证明是之前已经创建过了,然后再从弱引用中尝试获取实际Logger对象,如果获取不到则说明已经被GC清理掉了。

接下来是将Logger添加到用户上下文中,并且初始化Logger的level:

       // We're adding a new logger.
            // Note that we are creating a weak reference here.
            final LogManager owner = getOwner();
            logger.setLogManager(owner);
            ref = owner.new LoggerWeakRef(logger);
            namedLoggers.put(name, ref);

            // Apply any initial level defined for the new logger, unless
            // the logger's level is already initialized
            Level level = owner.getLevelProperty(name + ".level", null);
            if (level != null && !logger.isLevelInitialized()) {
                doSetLevel(logger, level);
            }

这里有一点说明一下,就是如果是一个新的Logger,在前面的方法里面通过构造方法创建的时候,是给了一个默认的INFO级别,然后在这里会通过配置文件再次寻找,如果我们对当前的类名称进行过特殊的配置

设置过其应该特殊处理的日志等级,那么这里会重新赋值。

// instantiation of the handler is done in the LogManager.addLogger
// implementation as a handler class may be only visible to LogManager
// subclass for the custom log manager case
processParentHandlers(logger, name);

接下来这个方式我们通过方法名可以知道是处理当前Logger节点的父类节点的Handler,我们跟进去看看:

        // If logger.getUseParentHandlers() returns 'true' and any of the logger's
        // parents have levels or handlers defined, make sure they are instantiated.
        private void processParentHandlers(final Logger logger, final String name) {
            final LogManager owner = getOwner();
            AccessController.doPrivileged(new PrivilegedAction<Void>() {
                @Override
                public Void run() {
                    if (logger != owner.rootLogger) {
                        boolean useParent = owner.getBooleanProperty(name + ".useParentHandlers", true);
                        if (!useParent) {
                            logger.setUseParentHandlers(false);
                        }
                    }
                    return null;
                }
            });

            int ix = 1;
            for (;;) {
                int ix2 = name.indexOf(".", ix);
                if (ix2 < 0) {
                    break;
                }
                String pname = name.substring(0, ix2);
                if (owner.getProperty(pname + ".level") != null ||
                    owner.getProperty(pname + ".handlers") != null) {
                    // This pname has a level/handlers definition.
                    // Make sure it exists.
                    demandLogger(pname, null);
                }
                ix = ix2+1;
            }
        }

代码很长但是逻辑还是比较清晰,首先就是通过配置文件判断一下,当前的Logger的name是否设置了使用父类的handler,如果找不到就认为是true,因为根Logger一般都是会打印到控制台的,所以默认情况下我们的Logger在处理日志的时候,会将其发送到根Logger也

进行处理,通常是打印到控制台中。

继续往下看,就是不断的切分遍历的去寻找,配置文件中是否有对应的level或者是handler,如果有就将其添加到命名空间中。

在将相关的父节点都添加到命名空间之后,就是为其建立节点树的过程了:

LogNode node = getNode(name);

首先是通过当前Logger节点的名字来获取LogNode对象,这个LogNode对象维护了Logger对象之间的父子关系,看一下这个getNode方法:

        LogNode getNode(String name) {
            if (name == null || name.equals("")) {
                return root;
            }
            LogNode node = root;
            while (name.length() > 0) {
                int ix = name.indexOf(".");
                String head;
                if (ix > 0) {
                    head = name.substring(0, ix);
                    name = name.substring(ix + 1);
                } else {
                    head = name;
                    name = "";
                }
                if (node.children == null) {
                    node.children = new HashMap<>();
                }
                LogNode child = node.children.get(head);
                if (child == null) {
                    child = new LogNode(node, this);
                    node.children.put(head, child);
                }
                node = child;
            }
            return node;
        }

这个方法主要就是将name用点分割符进行分割,然后利用LogNode对象构建起树形结构最后返回的是当前的节点,下面我们来看一下得到当前Logger几点之后做了什么:

// Find the new node and its parent.
            LogNode node = getNode(name);
            node.loggerRef = ref;
            Logger parent = null;
            LogNode nodep = node.parent;
            while (nodep != null) {
                LoggerWeakRef nodeRef = nodep.loggerRef;
                if (nodeRef != null) {
                    parent = nodeRef.get();
                    if (parent != null) {
                        break;
                    }
                }
                nodep = nodep.parent;
            }

            if (parent != null) {
                doSetParent(logger, parent);
            }
            // Walk over the children and tell them we are their new parent.
            node.walkAndSetParent(logger);
            // new LogNode is ready so tell the LoggerWeakRef about it
            ref.setNode(node);

这里首先是获得了当前Logger的LogNode节点,然后将Logger对象赋值给loggerRef属性中,也就是说实际上我们记录日志的Logger是保存在LogNode里面的

接下来我们尝试获取 nodep 节点,然后下面是一个while循环,这是因为上面我们虽然将通过点分割将所有的父类节点都添加到树中了,但是并不是每个父类几点都是有实际Logger的

比如我们的name叫做A.B.C,那么我们实际上只有一个Logger对象保存在C的LogNode里面,而A和B的LogNode里面是没有Logger对象的,所以遍历的去寻找到真正的存在Logger的父类LogNode

 之后的 walkAndSetParent 也是将当前节点的所有不为空的子节点的父节点设置为当前的logger对象。就是为了处理上面说的A和BLogNode虽然都是C的父节点,但是其实节点内并不存在实际的Logger对象的问题。

 

说到这里关于 addLocalLogger 的内容就已经详细的介绍完了,总结一下就是说,将一个新的Logger对象添加到用户的上下文中,然后初始化这个Logger,为其设置Level,维护树形关系,但是这个Logger对应的handler还没有处理呢。

所以继续看上面的 addLogger  方法,在处理完 addLocalLogger 之后,有一个方法  loadLoggerHandlers ,我们来看看其中做了什么:

private void loadLoggerHandlers(final Logger logger, final String name,
                                    final String handlersPropertyName)
    {
        AccessController.doPrivileged(new PrivilegedAction<Object>() {
            @Override
            public Object run() {
                String names[] = parseClassNames(handlersPropertyName);
                for (int i = 0; i < names.length; i++) {
                    String word = names[i];
                    try {
                        Class<?> clz = ClassLoader.getSystemClassLoader().loadClass(word);
                        Handler hdl = (Handler) clz.newInstance();
                        // Check if there is a property defining the
                        // this handler's level.
                        String levs = getProperty(word + ".level");
                        if (levs != null) {
                            Level l = Level.findLevel(levs);
                            if (l != null) {
                                hdl.setLevel(l);
                            } else {
                                // Probably a bad level. Drop through.
                                System.err.println("Can't set level for " + word);
                            }
                        }
                        // Add this Handler to the logger
                        logger.addHandler(hdl);
                    } catch (Exception ex) {
                        System.err.println("Can't load log handler \"" + word + "\"");
                        System.err.println("" + ex);
                        ex.printStackTrace();
                    }
                }
                return null;
            }
        });
    }

这里首先是通过 handlersPropertyName 去配置文件中寻找对应的配置,如果找不到则就沿用父类的Handler,如果找到了就会通过System Classloader进行加载,然后再寻找对应的handler的level,最后将handler添加到当前的logger对象中。


 

所以到目前为止,Logger的创建以及初始化,对应的Handler都已经说清楚了,但是有一个问题,就是我们在实际的应用中我们不会直接利用系统的默认配置将其输出到控制台的,我们是需要将日志保存到日志文件中处理的,那么这其中有哪些不一样的呢?

首先我们来看一个demo,通过配置文件来修改日志的配置:

    static String strClassName = Test2.class.getName();
    static Logger logger = Logger.getLogger(strClassName);
    static LogManager logManager = LogManager.getLogManager();
    
    static {
        InputStream inputStream = null;
        try {
            //读取配制文件
            inputStream = new ClassPathResource("logging.properties").getInputStream();
            logManager.readConfiguration(inputStream);
            //添加Logger
            logManager.addLogger(logger);
        } catch (SecurityException e) {
            e.printStackTrace();
        } catch (IOException e) {
            e.printStackTrace();
        }
    }

    public static void main(String[] args) {
        logger.severe("[severe]除数不能为0.");
        logger.warning("[warning]除数不能为0.");
        logger.info("[info]除数不能为0.");
        logger.config("[config]除数不能为0.");
        logger.fine("[fine]除数不能为0.");
        logger.finer("[finer]除数不能为0.");
        logger.finest("[finest]除数不能为0.");
    }

 这里也说明一下我的配置文件中的关键配置:

.level= ALL
java.util.logging.ConsoleHandler.level
= INFO
handlers= java.util.logging.FileHandler, java.util.logging.ConsoleHandler

通过运行结果可以看到在控制台中是打印出了INFO以上的3级日志,然后在日志文件中是把全部级别的日志都打印出来了。

但是在文章的最开始我们可以看到只是打印出了INFO以上的3级日志。

解释一下原因:我们如果直接获取Logger,那么其RootLogger是默认INFO级别的,然后Handler只有控制台,但是当我们读取了配置文件的配置之后,我们将全局的日志级别设置成了ALL,但是 ConsoleHandler 的输出级别为INFO,然后因为我们都没有设置不继承父类

那么我们在代码中创建的Logger就会继承父类RootLogger的日志级别和Handler。

那么就是说在LogManager读取配置文件的时候,应该是重置了日志级别和Handler,带着猜想我们去看看源码中的逻辑是不是这样。

public void readConfiguration(InputStream ins) throws IOException, SecurityException {
        checkPermission();
        reset();

我们就从这个 readConfiguration 方法入手,首先是权限检查,然后是一个reset方法:

    public void reset() throws SecurityException {
        checkPermission();
        synchronized (this) {
            props = new Properties();
            // Since we are doing a reset we no longer want to initialize
            // the global handlers, if they haven't been initialized yet.
            initializedGlobalHandlers = true;
        }
        for (LoggerContext cx : contexts()) {
            Enumeration<String> enum_ = cx.getLoggerNames();
            while (enum_.hasMoreElements()) {
                String name = enum_.nextElement();
                Logger logger = cx.findLogger(name);
                if (logger != null) {
                    resetLogger(logger);
                }
            }
        }
    }

这里遍历系统上下文和用户上下文,取出所有的Logger,然后执行resetLogger方法:

    private void resetLogger(Logger logger) {
        // Close all the Logger's handlers.
        Handler[] targets = logger.getHandlers();
        for (int i = 0; i < targets.length; i++) {
            Handler h = targets[i];
            logger.removeHandler(h);
            try {
                h.close();
            } catch (Exception ex) {
                // Problems closing a handler?  Keep going...
            }
        }
        String name = logger.getName();
        if (name != null && name.equals("")) {
            // This is the root logger.
            logger.setLevel(defaultLevel);
        } else {
            logger.setLevel(null);
        }
    }

这个方法只做了两件事:1->将Logger对应的Handler清空  2->将Logger的日志级别设置为默认级别,这里的defaultLevel为INFO

 props.load(ins);
        // Instantiate new configuration objects.
        String names[] = parseClassNames("config");

        for (int i = 0; i < names.length; i++) {
            String word = names[i];
            try {
                Class<?> clz = ClassLoader.getSystemClassLoader().loadClass(word);
                clz.newInstance();
            } catch (Exception ex) {
                System.err.println("Can't load config class \"" + word + "\"");
                System.err.println("" + ex);
                // ex.printStackTrace();
            }
        }

重置之后,通过输入流重新加载了配置文件Properties,下面这个是在配置文件中找到config的配置项,然后把对应的类添加到JVM中,但是没找到哪里会使用。

setLevelsOnExistingLoggers();

接下来是一个方法,我们通过方法名应该也能知道,是要对之前已经存在的Logger重新设置日志级别:

    // Private method to be called when the configuration has
    // changed to apply any level settings to any pre-existing loggers.
    synchronized private void setLevelsOnExistingLoggers() {
        Enumeration<?> enum_ = props.propertyNames();
        while (enum_.hasMoreElements()) {
            String key = (String)enum_.nextElement();
            if (!key.endsWith(".level")) {
                // Not a level definition.
                continue;
            }
            int ix = key.length() - 6;
            String name = key.substring(0, ix);
            Level level = getLevelProperty(key, null);
            if (level == null) {
                System.err.println("Bad level value for property: " + key);
                continue;
            }
            for (LoggerContext cx : contexts()) {
                Logger l = cx.findLogger(name);
                if (l == null) {
                    continue;
                }
                l.setLevel(level);
            }
        }
    }

逻辑很简单,就是在读取的配置文件中找到所有以 .level结尾的配置,然后把最后的 .level去掉就是对应Logger的名字,然后把配置文件中的Logger设置上去就可以了。

最后就是会调用监听器发送通知,这样设置了监听事件的部分就可以根据事件来进行相应的处理了。


   好了,上面我们已经知道Logger是怎么获取的了,下面就是通过Logger来记录日志的环节了

logger.info("[info]除数不能为0.");

  我们一般都是通过这种方式来记录日志,接下来我们看看这个方法的内部做了什么

    public void log(Level level, String msg) {
        if (!isLoggable(level)) {
            return;
        }
        LogRecord lr = new LogRecord(level, msg);
        doLog(lr);
    }

这里的Level就是我们调用的记录级别,然后isLoggable方法里面判断了这个级别与当前Logger日志级别的关系

    public boolean isLoggable(Level level) {
        if (level.intValue() < levelValue || levelValue == offValue) {
            return false;
        }
        return true;
    }

只有当前记录的日志级别大于Logger的级别才会被记录,否则会直接返回false,也就不会被处理了

经过日志级别的判断,通过msg参数来构造LogRecord对象,这个对象是在整个日志记录流程中的一个传输对象,我们看看构造的过程

    public LogRecord(Level level, String msg) {
        // Make sure level isn't null, by calling random method.
        level.getClass();
        this.level = level;
        message = msg;
        // Assign a thread ID and a unique sequence number.
        sequenceNumber = globalSequenceNumber.getAndIncrement();
        threadID = defaultThreadID();
        millis = System.currentTimeMillis();
        needToInferCaller = true;
   }

设置了一些初始化的变量,用于后续的传递,把我们记录的日志msg保存了起来。

继续看doLog方法里面做了什么

    // private support method for logging.
    // We fill in the logger name, resource bundle name, and
    // resource bundle and then call "void log(LogRecord)".
    private void doLog(LogRecord lr) {
        lr.setLoggerName(name);
        final LoggerBundle lb = getEffectiveLoggerBundle();
        final ResourceBundle  bundle = lb.userBundle;
        final String ebname = lb.resourceBundleName;
        if (ebname != null && bundle != null) {
            lr.setResourceBundleName(ebname);
            lr.setResourceBundle(bundle);
        }
        log(lr);
    }

通过上面的两行注释我们可以知道,这个方法也没有做什么特别的处理,只是添加了名称,还有国际化的一些对象,那么真正的处理逻辑应该是在这个log方法里面

/**
     * Log a LogRecord.
     * <p>
     * All the other logging methods in this class call through
     * this method to actually perform any logging.  Subclasses can
     * override this single method to capture all log activity.
     *
     * @param record the LogRecord to be published
     */
    public void log(LogRecord record) {
        if (!isLoggable(record.getLevel())) {
            return;
        }
        Filter theFilter = filter;
        if (theFilter != null && !theFilter.isLoggable(record)) {
            return;
        }

        // Post the LogRecord to all our Handlers, and then to
        // our parents' handlers, all the way up the tree.

        Logger logger = this;
        while (logger != null) {
            final Handler[] loggerHandlers = isSystemLogger
                ? logger.accessCheckedHandlers()
                : logger.getHandlers();

            for (Handler handler : loggerHandlers) {
                handler.publish(record);
            }

            final boolean useParentHdls = isSystemLogger
                ? logger.useParentHandlers
                : logger.getUseParentHandlers();

            if (!useParentHdls) {
                break;
            }

            logger = isSystemLogger ? logger.parent : logger.getParent();
        }
    }

方法逻辑比较清晰,首先就是检查级别和handler是否合法,但是这里有一个地方需要注意,就是FIlter。开篇我们说过每个Logger和Handler都可以设置一个FIlter,用于控制LogRecord是否可以被处理,但是在之类的FilterJDK只给了我们一个接口,而且是一个函数式接口,没有给任何实现。这就是说在我们使用过程中可以自行设置和开发。

比如这里我简单写一个例子:

    private static final Logger logger = Logger.getLogger(Loggg.class.getName());
    static {
        Filter earnMoneyFilter = logRecord ->  logRecord.getMessage().contains("syrup");
        logger.setFilter(earnMoneyFilter);
    }

这里就是只有日志里面的内容包含syrup的时候才会被处理,比较简单,这个在我们实际处理中根据需要进行处理即可。

 

接下来就是获取handlers,然后遍历每个handler,执行其中的publish方法,这个Handler是定义的一个接口,通过类关系我们可以看到主要使用的有:ConsoleHandler,FileHandler和SocketHandler。根据调用关系可以知道这几个Handler都是继承自StreamHandler,publish方法也是在这个类里面,我们这里就以 ConsoleHandler 为例子来看看里面的门道。

/**
 * Create a <tt>ConsoleHandler</tt> for <tt>System.err</tt>.
 * <p>
 * The <tt>ConsoleHandler</tt> is configured based on
 * <tt>LogManager</tt> properties (or their default values).
 *
 */
public ConsoleHandler() {
    sealed = false;
    configure();
    setOutputStream(System.err);
    sealed = true;
}

首先是构造方法,这里的sealed就是做标识使用,然后比较重要的是configure 方法和setOutputStream方法,我们逐一看一下:

private void configure() {
        LogManager manager = LogManager.getLogManager();
        String cname = getClass().getName();

        setLevel(manager.getLevelProperty(cname +".level", Level.INFO));
        setFilter(manager.getFilterProperty(cname +".filter", null));
        setFormatter(manager.getFormatterProperty(cname +".formatter", new SimpleFormatter()));
        try {
            setEncoding(manager.getStringProperty(cname +".encoding", null));
        } catch (Exception ex) {
            try {
                setEncoding(null);
            } catch (Exception ex2) {
                // doing a setEncoding with null should always work.
                // assert false;
            }
        }
    }

首先是 configure ,可以看到之类只是设置一下级别,filter 和Formatter 以及字符集这些信息,除此之外并没有做什么其他处理。

然后是setOutputStream方法:

/**
     * Change the output stream.
     * <P>
     * If there is a current output stream then the <tt>Formatter</tt>'s
     * tail string is written and the stream is flushed and closed.
     * Then the output stream is replaced with the new output stream.
     *
     * @param out   New output stream.  May not be null.
     * @exception  SecurityException  if a security manager exists and if
     *             the caller does not have <tt>LoggingPermission("control")</tt>.
     */
    protected synchronized void setOutputStream(OutputStream out) throws SecurityException {
        if (out == null) {
            throw new NullPointerException();
        }
        flushAndClose();
        output = out;
        doneHeader = false;
        String encoding = getEncoding();
        if (encoding == null) {
            writer = new OutputStreamWriter(output);
        } else {
            try {
                writer = new OutputStreamWriter(output, encoding);
            } catch (UnsupportedEncodingException ex) {
                // This shouldn't happen.  The setEncoding method
                // should have validated that the encoding is OK.
                throw new Error("Unexpected exception " + ex);
            }
        }
    }

通过构造方法的形参我们可以知道,这里的输出流是系统错误流,然后在这方法中将doneHeader设置为false,这个就是在configure的方法里面,我们看到了为当前的handler初始化了Formetter,那么有的不同的Formatter在输出的时候可能会需要不同的header让处理输出流的地方进行识别,所以针对不同的Formatter比如xml,就会在对应的XmlFormatter中提供对应的方法,用于返回指定的header,这个在下面会看到。

然后这里还有一个比较重要的就是初始化了writer,用于后面日志的记录。

看完了构造方法,我们继续来看看 publish 方法做了什么:

/**
     * Format and publish a <tt>LogRecord</tt>.
     * <p>
     * The <tt>StreamHandler</tt> first checks if there is an <tt>OutputStream</tt>
     * and if the given <tt>LogRecord</tt> has at least the required log level.
     * If not it silently returns.  If so, it calls any associated
     * <tt>Filter</tt> to check if the record should be published.  If so,
     * it calls its <tt>Formatter</tt> to format the record and then writes
     * the result to the current output stream.
     * <p>
     * If this is the first <tt>LogRecord</tt> to be written to a given
     * <tt>OutputStream</tt>, the <tt>Formatter</tt>'s "head" string is
     * written to the stream before the <tt>LogRecord</tt> is written.
     *
     * @param  record  description of the log event. A null record is
     *                 silently ignored and is not published
     */
    @Override
    public synchronized void publish(LogRecord record) {
        if (!isLoggable(record)) {
            return;
        }
        String msg;
        try {
            msg = getFormatter().format(record);
        } catch (Exception ex) {
            // We don't want to throw an exception here, but we
            // report the exception to any registered ErrorManager.
            reportError(null, ex, ErrorManager.FORMAT_FAILURE);
            return;
        }

        try {
            if (!doneHeader) {
                writer.write(getFormatter().getHead(this));
                doneHeader = true;
            }
            writer.write(msg);
        } catch (Exception ex) {
            // We don't want to throw an exception here, but we
            // report the exception to any registered ErrorManager.
            reportError(null, ex, ErrorManager.WRITE_FAILURE);
        }
    }

这里首先通过Formatter格式化了一下msg,就是将我们的内容转换成统一的格式,然后在下面就是通过doneHeader这个标志位来判断是否需要先输出header,然后再写入我们真事的日志信息,当所有的日志都写完之后,在我们最开始的地方ConsoleHandler .publish 方法里面会调用一次flush方法,把刚才写如的日志写到控制台中。

到这里我们就知道了,当我们通过Logger来记录日志的时候,首先是会将我们需要记录的信息包装成LogRecord对象,然后经过Handler来输出到指定的地方,但是我们忽略了一点,就是我们常用的Logger之间的继承在哪里处理的呢?

所以这里我把上面的一段代码再粘贴过来:

while (logger != null) {
            final Handler[] loggerHandlers = isSystemLogger
                ? logger.accessCheckedHandlers()
                : logger.getHandlers();

            for (Handler handler : loggerHandlers) {
                handler.publish(record);
            }

            final boolean useParentHdls = isSystemLogger
                ? logger.useParentHandlers
                : logger.getUseParentHandlers();

            if (!useParentHdls) {
                break;
            }

            logger = isSystemLogger ? logger.parent : logger.getParent();
        }

就是在Logger.log里面的这个方法我们刚才详细的看了for循环,现在我们来看一下for循环下面的内容,就是useParentHdls的对象,这个就是用于判断是否将日志消息交给父类Logger进行处理的一个标志,这里可以看到如果是系统Logger,那么这个变量是true。

然后下面会判断如果我们设置了false,那么日志信息就只是在当前的Logger配置的Handler中进行记录,然后就执行break的操作,完成日志记录了。

但是如果这个变量是true,那么就会通过下面的语句来获取当前Logger来获取其父Logger,然后在while循环中继续日志的处理。

 三、SLF4j(Simple Logging Facade for Java)

   首先我们还是来个例子,来看看SLF4J在项目中怎么使用:
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Slf4JTest {

    public static void main(String[] args) {
        Logger logger = LoggerFactory.getLogger(Slf4JTest.class);
        logger.info("Slf4JTest test log info");
    }
}

然后我们直接运行,在控制台却提示这个:

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

就是说无法输出日志,因为没有找到 org.slf4j.impl.StaticLoggerBinder ,这个前面我们聊过了,就是SLF4J是日志接口框架并没有提示日志输出的实现,所以这里还需要一个日志输出的实现框架的配合才能正确的打印日志

那么现在在日志接口层SLF4J基本上都是第一选择,然后日志的实现其实Log4j2的性能更加好一些,所以这里我们需要一个Log4J的日志实现的依赖,然后需要一个SLF4J和LOG4J的桥接包,下面给出相关POM

     <!--SLF4J核心包-->
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-api</artifactId>
            <version>1.7.7</version>
        </dependency>
        <!--SLF4J与Log4J2的桥接包-->
        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-slf4j-impl</artifactId>
            <version>2.9.1</version>
        </dependency>
        <!--Log4j2的核心包-->
        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-api</artifactId>
            <version>2.9.1</version>
        </dependency>
        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-core</artifactId>
            <version>2.9.1</version>
        </dependency>

这里注意如果是web项目还需要一个log4j-web的依赖

添加了上述依赖之后,还需要在resources中添加一个log4j2.xml的配置文件,之后我们就可以通过slf4j的接口打印日志了,还是开始的代码,我们来看看这次控制台输出的是什么吧

[2020-05-11 14:25:54,936][INFO ][main][log.Slf4JTest][log.Slf4JTest.main(Slf4JTest.java:10)][] Slf4JTest test log info

 下面我们就开始看看SLF4J 的工作原理:

  /**
   * Return a logger named according to the name parameter using the statically
   * bound {@link ILoggerFactory} instance.
   *
   * @param name The name of the logger.
   * @return logger
   */
  public static Logger getLogger(String name) {
    ILoggerFactory iLoggerFactory = getILoggerFactory();
    return iLoggerFactory.getLogger(name);
  }

首先是获取ILoggerFactory对象,然后通过这个工厂对象来获取Logger实例,那么就看看ILoggerFactory工厂里面做了什么:

  /**
   * Return the {@link ILoggerFactory} instance in use.
   * <p/>
   * <p/>
   * ILoggerFactory instance is bound with this class at compile time.
   *
   * @return the ILoggerFactory instance in use
   */
  public static ILoggerFactory getILoggerFactory() {
    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://bugzilla.slf4j.org/show_bug.cgi?id=106
        return TEMP_FACTORY;
    }
    throw new IllegalStateException("Unreachable code");
  }

首先是 INITIALIZATION_STATE ,这是一个静态变量,初始值是未初始化。那么如果第一次调用,就会把状态改为初始化进行中,然后执行 performInitialization() 方法,所以这个方法里面应该是执行了具体的初始化操作

然后下面是根据不同的状态返回不同的Builder对象,我们进入到  performInitialization() 中看看:

  private final static void performInitialization() {
    bind();
    if (INITIALIZATION_STATE == SUCCESSFUL_INITIALIZATION) {
      versionSanityCheck();
    }
  }

调用一个私有的bind()方法,最后是如果初始化成功了,就检查一下版本,这个我们稍后会看,先看一下bind方法

private final static void bind() {
    try {
      Set<URL> staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
      reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
      // the next line does the binding
      StaticLoggerBinder.getSingleton();
      INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
      reportActualBinding(staticLoggerBinderPathSet);
      fixSubstitutedLoggers();
    } 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.indexOf("org.slf4j.impl.StaticLoggerBinder.getSingleton()") != -1) {
        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);
    }
  }

内容比较长,我们一点一点来,首先是 findPossibleStaticLoggerBinderPathSet() 方法,通过方法名称我们可以猜测是用来寻找可能的实现类的集合

private static String STATIC_LOGGER_BINDER_PATH = "org/slf4j/impl/StaticLoggerBinder.class";
private 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 = (URL) paths.nextElement();
        staticLoggerBinderPathSet.add(path);
      }
    } catch (IOException ioe) {
      Util.report("Error getting resources from path", ioe);
    }
    return staticLoggerBinderPathSet;
  }

这里应该就是SLF4J最精华的地方了,因为前文我们说过Log4J的作者Ceki与Apache闹掰了是因为意见不合,其实很大程度上就是不满意这个实现类的寻找机制,那么SLF4J是怎么做的呢?就在这个方法里面了

这里提供了一个静态字符串 STATIC_LOGGER_BINDER_PATH , 这个就是日志实现类的路径,所有想要使用SLF4J的日志框架,都要有这个实现类,然后在SLF4J这里通过类加载器就可以获取对应的日志是西安对象,是不是很巧妙又非常简单

但是这里考虑到我们项目中可能会出现多个不同的实现,比如我们有Logback 和 Log4j2,那么就它就不知道该用哪个了,所以这个时候最好的办法就是然用户去选择,所以接下来就有了 reportMultipleBindingAmbiguity方法:

  /**
   * Prints a warning message on the console if multiple bindings were found on the class path.
   * No reporting is done otherwise.
   *
   */
  private static void reportMultipleBindingAmbiguity(Set<URL> staticLoggerBinderPathSet) {
    if (isAmbiguousStaticLoggerBinderPathSet(staticLoggerBinderPathSet)) {
      Util.report("Class path contains multiple SLF4J bindings.");
      Iterator<URL> iterator = staticLoggerBinderPathSet.iterator();
      while (iterator.hasNext()) {
        URL path = (URL) iterator.next();
        Util.report("Found binding in [" + path + "]");
      }
      Util.report("See " + MULTIPLE_BINDINGS_URL + " for an explanation.");
    }
  }

这里就是根据刚才我们得到的日志实现类的集合进行遍历判断,如果集合中的数量大于1,那就证明有多个日志实现类的存在

如果恰好只找到一个合适的日志实现,那么会调用一下他的  StaticLoggerBinder.getSingleton(); 方法,这里因为我们选择的日志实现是log4j2,那么就看看在log4j2这里做了什么:

private StaticLoggerBinder() {
        loggerFactory = new Log4jLoggerFactory();
}
private static final StaticLoggerBinder SINGLETON = new StaticLoggerBinder();
/**
 * Returns the singleton of this class.
 *
 * @return the StaticLoggerBinder singleton
*/
public static StaticLoggerBinder getSingleton() {
        return SINGLETON;
    }

通过构造方法初始化了一个 Log4jLoggerFactory 的Logger工厂,然后返回了 StaticLoggerBinder 的单例对象,其实这里主要是为了获取Logger的工厂对象

处理完这些之后,就基本完成了初始化,接下来改变了一下状态,然后打印出当前找到的日志实现类是哪一个,最后有一个 fixSubstitutedLoggers 有点意思

大家应该还记得在前文中个 ONGOING_INITIALIZATION 的状态,然后会返回一个  SubstituteLoggerFactory 的工厂对象,也就是在还未初始化完成的时候,都是通过这个工厂对象来返回Logger的,同样返回的都是 SubstituteLogger

这个Logger实际上在没有设置deleget logger的时候,真正的实现是一个 NOPLogger,简单来看就是 no operation logger 

所以在我们进行初始化的过程中,这个Logger只是为了保证程序不报错,但是实际的日志内容是没有被记录的

所以回过来,我们看看 fixSubstitutedLoggers 方法做了什么:

 private final static void fixSubstitutedLoggers() {
    List<SubstituteLogger> loggers = TEMP_FACTORY.getLoggers();

    if(loggers.isEmpty()){
      return;
    }

    Util.report("The following set of substitute loggers may have been accessed");
    Util.report("during the initialization phase. Logging calls during this");
    Util.report("phase were not honored. However, subsequent logging calls to these");
    Util.report("loggers will work as normally expected.");
    Util.report("See also " + SUBSTITUTE_LOGGER_URL);
    for(SubstituteLogger subLogger : loggers){
      subLogger.setDelegate(getLogger(subLogger.getName()));
      Util.report(subLogger.getName());
    }

    TEMP_FACTORY.clear();
  }

获取所有的Logger,然后通过当前找到的实现类来生成对应的Logger,然后通过setDelegate方法设置委托,这样之前的Logger就能够用找到的实现类来记录日志了

最后把这个 TEMP_FACTORY 清空,后面的Logger获取以及关系的维护都是在对应的日志实现框架里完成。

初始化的方法看完了,接下来我们看看之前提到的版本校验:

  private final static void versionSanityCheck() {
    try {
      String requested = StaticLoggerBinder.REQUESTED_API_VERSION;

      boolean match = false;
      for (int i = 0; i < API_COMPATIBILITY_LIST.length; i++) {
        if (requested.startsWith(API_COMPATIBILITY_LIST[i])) {
          match = true;
        }
      }
      if (!match) {
        Util.report("The requested version " + requested
                + " by your slf4j binding is not compatible with "
                + Arrays.asList(API_COMPATIBILITY_LIST).toString());
        Util.report("See " + VERSION_MISMATCH + " for further details.");
      }
    } catch (java.lang.NoSuchFieldError nsfe) {
      // given our large user base and SLF4J's commitment to backward
      // compatibility, we cannot cry here. Only for implementations
      // which willingly declare a REQUESTED_API_VERSION field do we
      // emit compatibility warnings.
    } catch (Throwable e) {
      // we should never reach here
      Util.report("Unexpected problem occured during version sanity check", e);
    }
  }

这里的requested是在 StaticLoggerBinder 类面的属性,也就是不同的日志实现,值会有所不同,然后在SLF4J里面是通过API_COMPATIBILITY_LIST数组来指定支持的JDK版本的,就是判断一个JDK的环境是否满足条件

上面我们分析了SLF4J是怎么找到适合的日志实现类的,然后获取到ILoggerFactory的工厂对象,这个具体的工厂是由日志实现框架来实现的,所以后面获取Logger,都是通过这个工厂对象来完成的

这样SLF4J就完成了接口到日志实现的一个绑定,在代码中我们就只需要针对SLF4J进行开发就好了,不会与实际的日志实现框架过度耦合。

这样在代码中虽然我们是调用SLF4J的Logger对象来记录日志,但是这个Logger的实现类,是对应的日志实现框架的了。

 

 

 已经是log4j2的实现对象了.

posted @ 2020-03-20 16:21  SyrupzZ  阅读(521)  评论(0)    收藏  举报