前言

log4j2是apache在log4j的基础上，参考logback架构实现的一套新的日志系统（我感觉是apache害怕logback了）。

log4j2的上写着一些它的优点：

• 在拥有全部logback特性的情况下，还修复了一些隐藏问题
• API 分离：现在log4j2也是门面模式使用日志，默认的日志实现是log4j2，当然你也可以用logback（应该没有人会这么做）
• 性能提升：log4j2包含下一代基于LMAX Disruptor library的异步logger，在多线程场景下，拥有18倍于log4j和logback的性能
• 多API支持：log4j2提供Log4j 1.2, SLF4J, Commons Logging and java.util.logging (JUL) 的API支持
• 避免锁定：使用Log4j2 API的应用程序始终可以选择使用任何符合SLF4J的库作为log4j-to-slf4j适配器的记录器实现
• 自动重新加载配置：与Logback一样，Log4j 2可以在修改时自动重新加载其配置。与Logback不同，它会在重新配置发生时不会丢失日志事件。
• 高级过滤： 与Logback一样，Log4j 2支持基于Log事件中的上下文数据，标记，正则表达式和其他组件进行过滤。
• 插件架构： Log4j使用插件模式配置组件。因此，您无需编写代码来创建和配置Appender，Layout，Pattern Converter等。Log4j自动识别插件并在配置引用它们时使用它们。
• 属性支持：您可以在配置中引用属性，Log4j将直接替换它们，或者Log4j将它们传递给将动态解析它们的底层组件。
• Java 8 Lambda支持
• 自定义日志级别
• 产生垃圾少：在稳态日志记录期间，Log4j 2 在独立应用程序中是无垃圾的，在Web应用程序中是低垃圾。这减少了垃圾收集器的压力，并且可以提供更好的响应时间性能。
• 和应用server集成：版本2.10.0引入了一个模块log4j-appserver，以改进与Apache Tomcat和Eclipse Jetty的集成。

Log4j2类图：

这次从四个地方去探索源码：启动，配置，异步，插件化

源码探索

启动

log4j2的关键组件

• LogManager

根据配置指定LogContexFactory，初始化对应的LoggerContext

• LoggerContext

1、解析配置文件，解析为对应的java对象。

2、通过LoggerRegisty缓存Logger配置

3、Configuration配置信息

4、start方法解析配置文件，转化为对应的java对象

5、通过getLogger获取logger对象

• Logger

LogManaer

该组件是Log4J启动的入口，后续的LoggerContext以及Logger都是通过调用LogManager的静态方法获得。我们可以使用下面的代码获取Logger

Logger logger = LogManager.getLogger();

可以看出LogManager是十分关键的组件，因此在这个小节中我们详细分析LogManager的启动流程。

LogManager启动的入口是下面的static代码块：

/**     * Scans the classpath to find all logging implementation. Currently, only one will be used but this could be     * extended to allow multiple implementations to be used.     */    static {        // Shortcut binding to force a specific logging implementation.        final PropertiesUtil managerProps = PropertiesUtil.getProperties();        final String factoryClassName = managerProps.getStringProperty(FACTORY_PROPERTY_NAME);        if (factoryClassName != null) {            try {                factory = LoaderUtil.newCheckedInstanceOf(factoryClassName, LoggerContextFactory.class);            } catch (final ClassNotFoundException cnfe) {                LOGGER.error("Unable to locate configured LoggerContextFactory {}", factoryClassName);            } catch (final Exception ex) {                LOGGER.error("Unable to create configured LoggerContextFactory {}", factoryClassName, ex);            }        }        if (factory == null) {            final SortedMap
    
      factories = new TreeMap<>();            // note that the following initial call to ProviderUtil may block until a Provider has been installed when            // running in an OSGi environment            if (ProviderUtil.hasProviders()) {                for (final Provider provider : ProviderUtil.getProviders()) {                    final Class
      factoryClass = provider.loadLoggerContextFactory();                    if (factoryClass != null) {                        try {                            factories.put(provider.getPriority(), factoryClass.newInstance());                        } catch (final Exception e) {                            LOGGER.error("Unable to create class {} specified in provider URL {}", factoryClass.getName(), provider                                    .getUrl(), e);                        }                    }                }                if (factories.isEmpty()) {                    LOGGER.error("Log4j2 could not find a logging implementation. "                            + "Please add log4j-core to the classpath. Using SimpleLogger to log to the console...");                    factory = new SimpleLoggerContextFactory();                } else if (factories.size() == 1) {                    factory = factories.get(factories.lastKey());                } else {                    final StringBuilder sb = new StringBuilder("Multiple logging implementations found: \n");                    for (final Map.Entry
     
       entry : factories.entrySet()) {                        sb.append("Factory: ").append(entry.getValue().getClass().getName());                        sb.append(", Weighting: ").append(entry.getKey()).append('\n');                    }                    factory = factories.get(factories.lastKey());                    sb.append("Using factory: ").append(factory.getClass().getName());                    LOGGER.warn(sb.toString());                }            } else {                LOGGER.error("Log4j2 could not find a logging implementation. "                        + "Please add log4j-core to the classpath. Using SimpleLogger to log to the console...");                factory = new SimpleLoggerContextFactory();            }        }    }
     
    

这段静态代码段主要分为下面的几个步骤：

1. 首先根据特定配置文件的配置信息获取loggerContextFactory
2. 如果没有找到对应的Factory的实现类则通过ProviderUtil中的getProviders()方法载入providers，随后通过provider的loadLoggerContextFactory方法载入LoggerContextFactory的实现类
3. 如果provider中没有获取到LoggerContextFactory的实现类或provider为空，则使用SimpleLoggerContextFactory作为LoggerContextFactory。

根据配置文件载入LoggerContextFactory

// Shortcut binding to force a specific logging implementation.        final PropertiesUtil managerProps = PropertiesUtil.getProperties();        final String factoryClassName = managerProps.getStringProperty(FACTORY_PROPERTY_NAME);        if (factoryClassName != null) {            try {                factory = LoaderUtil.newCheckedInstanceOf(factoryClassName, LoggerContextFactory.class);            } catch (final ClassNotFoundException cnfe) {                LOGGER.error("Unable to locate configured LoggerContextFactory {}", factoryClassName);            } catch (final Exception ex) {                LOGGER.error("Unable to create configured LoggerContextFactory {}", factoryClassName, ex);            }        }

在这段逻辑中，LogManager优先通过配置文件”log4j2.component.properties”通过配置项”log4j2.loggerContextFactory”来获取LoggerContextFactory，如果用户做了对应的配置，通过newCheckedInstanceOf方法实例化LoggerContextFactory的对象，最终的实现方式为：

public static 
    
      T newInstanceOf(final Class
     
       clazz)            throws InstantiationException, IllegalAccessException, InvocationTargetException {        try {            return clazz.getConstructor().newInstance();        } catch (final NoSuchMethodException ignored) {            // FIXME: looking at the code for Class.newInstance(), this seems to do the same thing as above            return clazz.newInstance();        }    }
     
    

在默认情况下，不存在初始的默认配置文件log4j2.component.properties，因此需要从其他途径获取LoggerContextFactory。

通过Provider实例化LoggerContextFactory对象

代码：

if (factory == null) {            final SortedMap
    
      factories = new TreeMap<>();            // note that the following initial call to ProviderUtil may block until a Provider has been installed when            // running in an OSGi environment            if (ProviderUtil.hasProviders()) {                for (final Provider provider : ProviderUtil.getProviders()) {                    final Class
      factoryClass = provider.loadLoggerContextFactory();                    if (factoryClass != null) {                        try {                            factories.put(provider.getPriority(), factoryClass.newInstance());                        } catch (final Exception e) {                            LOGGER.error("Unable to create class {} specified in provider URL {}", factoryClass.getName(), provider                                    .getUrl(), e);                        }                    }                }                if (factories.isEmpty()) {                    LOGGER.error("Log4j2 could not find a logging implementation. "                            + "Please add log4j-core to the classpath. Using SimpleLogger to log to the console...");                    factory = new SimpleLoggerContextFactory();                } else if (factories.size() == 1) {                    factory = factories.get(factories.lastKey());                } else {                    final StringBuilder sb = new StringBuilder("Multiple logging implementations found: \n");                    for (final Map.Entry
     
       entry : factories.entrySet()) {                        sb.append("Factory: ").append(entry.getValue().getClass().getName());                        sb.append(", Weighting: ").append(entry.getKey()).append('\n');                    }                    factory = factories.get(factories.lastKey());                    sb.append("Using factory: ").append(factory.getClass().getName());                    LOGGER.warn(sb.toString());                }            } else {                LOGGER.error("Log4j2 could not find a logging implementation. "                        + "Please add log4j-core to the classpath. Using SimpleLogger to log to the console...");                factory = new SimpleLoggerContextFactory();            }        }
     
    

这里比较有意思的是hasProviders和getProviders都会通过线程安全的方式去懒加载ProviderUtil这个对象。跟进lazyInit方法：

protected static void lazyInit() {        //noinspection DoubleCheckedLocking        if (INSTANCE == null) {            try {                STARTUP_LOCK.lockInterruptibly();                if (INSTANCE == null) {                    INSTANCE = new ProviderUtil();                }            } catch (final InterruptedException e) {                LOGGER.fatal("Interrupted before Log4j Providers could be loaded.", e);                Thread.currentThread().interrupt();            } finally {                STARTUP_LOCK.unlock();            }        }    }

再看构造方法：

private ProviderUtil() {        for (final LoaderUtil.UrlResource resource : LoaderUtil.findUrlResources(PROVIDER_RESOURCE)) {            loadProvider(resource.getUrl(), resource.getClassLoader());        }    }

这里的懒加载其实就是懒加载Provider对象。在创建新的providerUtil实例的过程中就会直接实例化provider对象，其过程是先通过getClassLoaders方法获取provider的类加载器，然后通过loadProviders(classLoader);加载类。在providerUtil实例化的最后，会统一查找”META-INF/log4j-provider.properties”文件中对应的provider的url，会考虑从远程加载provider。而loadProviders方法就是在ProviderUtil的PROVIDERS列表中添加对一个的provider。可以看到默认的provider是org.apache.logging.log4j.core.impl.Log4jContextFactory

LoggerContextFactory = org.apache.logging.log4j.core.impl.Log4jContextFactoryLog4jAPIVersion = 2.1.0FactoryPriority= 10

很有意思的是这里懒加载加上了锁，而且使用的是

lockInterruptibly这个方法。lockInterruptibly和lock的区别如下：

lock 与 lockInterruptibly比较区别在于：

lock 优先考虑获取锁，待获取锁成功后，才响应中断。

lockInterruptibly 优先考虑响应中断，而不是响应锁的普通获取或重入获取。 ReentrantLock.lockInterruptibly允许在等待时由其它线程调用等待线程的 Thread.interrupt 方法来中断等待线程的等待而直接返回，这时不用获取锁，而会抛出一个InterruptedException。 ReentrantLock.lock方法不允许Thread.interrupt中断,即使检测到Thread.isInterrupted,一样会继续尝试获取锁，失败则继续休眠。只是在最后获取锁成功后再把当前线程置为interrupted状态,然后再中断线程。

上面有一句注释值得注意：

/**     * Guards the ProviderUtil singleton instance from lazy initialization. This is primarily used for OSGi support.     *     * @since 2.1     */    protected static final Lock STARTUP_LOCK = new ReentrantLock();    // STARTUP_LOCK guards INSTANCE for lazy initialization; this allows the OSGi Activator to pause the startup and    // wait for a Provider to be installed. See LOG4J2-373    private static volatile ProviderUtil INSTANCE;

原来这里是为了让osgi可以阻止启动。

再回到logManager： 可以看到在加载完Provider之后，会做factory的绑定：

if (factories.isEmpty()) {                    LOGGER.error("Log4j2 could not find a logging implementation. "                            + "Please add log4j-core to the classpath. Using SimpleLogger to log to the console...");                    factory = new SimpleLoggerContextFactory();                } else if (factories.size() == 1) {                    factory = factories.get(factories.lastKey());                } else {                    final StringBuilder sb = new StringBuilder("Multiple logging implementations found: \n");                    for (final Map.Entry
    
      entry : factories.entrySet()) {                        sb.append("Factory: ").append(entry.getValue().getClass().getName());                        sb.append(", Weighting: ").append(entry.getKey()).append('\n');                    }                    factory = factories.get(factories.lastKey());                    sb.append("Using factory: ").append(factory.getClass().getName());                    LOGGER.warn(sb.toString());                }
    

到这里，logmanager的启动流程就结束了。

配置

在不使用slf4j的情况下，我们获取logger的方式是这样的：

Logger logger = logManager.getLogger(xx.class)

跟进getLogger方法：

public static Logger getLogger(final Class
     clazz) {        final Class
     cls = callerClass(clazz);        return getContext(cls.getClassLoader(), false).getLogger(toLoggerName(cls));    }

这里有一个getContext方法，跟进，

public static LoggerContext getContext(final ClassLoader loader, final boolean currentContext) {        try {            return factory.getContext(FQCN, loader, null, currentContext);        } catch (final IllegalStateException ex) {            LOGGER.warn(ex.getMessage() + " Using SimpleLogger");            return new SimpleLoggerContextFactory().getContext(FQCN, loader, null, currentContext);        }    }

上文提到factory的具体实现是Log4jContextFactory，跟进getContext

方法：

public LoggerContext getContext(final String fqcn, final ClassLoader loader, final Object externalContext,                                    final boolean currentContext) {        final LoggerContext ctx = selector.getContext(fqcn, loader, currentContext);        if (externalContext != null && ctx.getExternalContext() == null) {            ctx.setExternalContext(externalContext);        }        if (ctx.getState() == LifeCycle.State.INITIALIZED) {            ctx.start();        }        return ctx;    }

直接看start：

public void start() {        LOGGER.debug("Starting LoggerContext[name={}, {}]...", getName(), this);        if (PropertiesUtil.getProperties().getBooleanProperty("log4j.LoggerContext.stacktrace.on.start", false)) {            LOGGER.debug("Stack trace to locate invoker",                    new Exception("Not a real error, showing stack trace to locate invoker"));        }        if (configLock.tryLock()) {            try {                if (this.isInitialized() || this.isStopped()) {                    this.setStarting();                    reconfigure();                    if (this.configuration.isShutdownHookEnabled()) {                        setUpShutdownHook();                    }                    this.setStarted();                }            } finally {                configLock.unlock();            }        }        LOGGER.debug("LoggerContext[name={}, {}] started OK.", getName(), this);    }

发现其中的核心方法是reconfigure方法，继续跟进：

private void reconfigure(final URI configURI) {        final ClassLoader cl = ClassLoader.class.isInstance(externalContext) ? (ClassLoader) externalContext : null;        LOGGER.debug("Reconfiguration started for context[name={}] at URI {} ({}) with optional ClassLoader: {}",                contextName, configURI, this, cl);        final Configuration instance = ConfigurationFactory.getInstance().getConfiguration(this, contextName, configURI, cl);        if (instance == null) {            LOGGER.error("Reconfiguration failed: No configuration found for '{}' at '{}' in '{}'", contextName, configURI, cl);        } else {            setConfiguration(instance);            /*             * instance.start(); Configuration old = setConfiguration(instance); updateLoggers(); if (old != null) {             * old.stop(); }             */            final String location = configuration == null ? "?" : String.valueOf(configuration.getConfigurationSource());            LOGGER.debug("Reconfiguration complete for context[name={}] at URI {} ({}) with optional ClassLoader: {}",                    contextName, location, this, cl);        }    }

可以看到每一个configuration都是从ConfigurationFactory拿出来的，我们先看看这个类的getInstance看看：

public static ConfigurationFactory getInstance() {        // volatile works in Java 1.6+, so double-checked locking also works properly        //noinspection DoubleCheckedLocking        if (factories == null) {            LOCK.lock();            try {                if (factories == null) {                    final List
    
      list = new ArrayList
     
      ();                    final String factoryClass = PropertiesUtil.getProperties().getStringProperty(CONFIGURATION_FACTORY_PROPERTY);                    if (factoryClass != null) {                        addFactory(list, factoryClass);                    }                    final PluginManager manager = new PluginManager(CATEGORY);                    manager.collectPlugins();                    final Map
      
       > plugins = manager.getPlugins();                    final List
       
        > ordered =                        new ArrayList
        
         >(plugins.size());                    for (final PluginType
          type : plugins.values()) {                        try {                            ordered.add(type.getPluginClass().asSubclass(ConfigurationFactory.class));                        } catch (final Exception ex) {                            LOGGER.warn("Unable to add class {}", type.getPluginClass(), ex);                        }                    }                    Collections.sort(ordered, OrderComparator.getInstance());                    for (final Class
          clazz : ordered) {                        addFactory(list, clazz);                    }                    // see above comments about double-checked locking                    //noinspection NonThreadSafeLazyInitialization                    factories = Collections.unmodifiableList(list);                }            } finally {                LOCK.unlock();            }        }        LOGGER.debug("Using configurationFactory {}", configFactory);        return configFactory;    }
        
       
      
     
    

这里可以看到ConfigurationFactory中利用了PluginManager来进行初始化，PluginManager会将ConfigurationFactory的子类加载进来，默认使用的XmlConfigurationFactory，JsonConfigurationFactory，YamlConfigurationFactory这三个子类，这里插件化加载暂时按下不表。

回到reconfigure这个方法，我们看到获取ConfigurationFactory实例之后会去调用getConfiguration方法：

public Configuration getConfiguration(final String name, final URI configLocation, final ClassLoader loader) {        if (!isActive()) {            return null;        }        if (loader == null) {            return getConfiguration(name, configLocation);        }        if (isClassLoaderUri(configLocation)) {            final String path = extractClassLoaderUriPath(configLocation);            final ConfigurationSource source = getInputFromResource(path, loader);            if (source != null) {                final Configuration configuration = getConfiguration(source);                if (configuration != null) {                    return configuration;                }            }        }        return getConfiguration(name, configLocation);    }

跟进getConfiguration，这里值得注意的是有很多个getConfiguration，注意甄别，如果不确定的话可以通过debug的方式来确定。

public Configuration getConfiguration(final String name, final URI configLocation) {            if (configLocation == null) {                final String config = this.substitutor.replace(                    PropertiesUtil.getProperties().getStringProperty(CONFIGURATION_FILE_PROPERTY));                if (config != null) {                    ConfigurationSource source = null;                    try {                        source = getInputFromUri(FileUtils.getCorrectedFilePathUri(config));                    } catch (final Exception ex) {                        // Ignore the error and try as a String.                        LOGGER.catching(Level.DEBUG, ex);                    }                    if (source == null) {                        final ClassLoader loader = LoaderUtil.getThreadContextClassLoader();                        source = getInputFromString(config, loader);                    }                    if (source != null) {                        for (final ConfigurationFactory factory : factories) {                            final String[] types = factory.getSupportedTypes();                            if (types != null) {                                for (final String type : types) {                                    if (type.equals("*") || config.endsWith(type)) {                                        final Configuration c = factory.getConfiguration(source);                                        if (c != null) {                                            return c;                                        }                                    }                                }                            }                        }                    }                }            } else {                for (final ConfigurationFactory factory : factories) {                    final String[] types = factory.getSupportedTypes();                    if (types != null) {                        for (final String type : types) {                            if (type.equals("*") || configLocation.toString().endsWith(type)) {                                final Configuration config = factory.getConfiguration(name, configLocation);                                if (config != null) {                                    return config;                                }                            }                        }                    }                }            }            Configuration config = getConfiguration(true, name);            if (config == null) {                config = getConfiguration(true, null);                if (config == null) {                    config = getConfiguration(false, name);                    if (config == null) {                        config = getConfiguration(false, null);                    }                }            }            if (config != null) {                return config;            }            LOGGER.error("No log4j2 configuration file found. Using default configuration: logging only errors to the console.");            return new DefaultConfiguration();        }

这里就会根据之前加载进来的factory进行配置的获取，具体的不再解析。

回到reconfigure，之后的步骤就是setConfiguration，入参就是刚才获取的config

private synchronized Configuration setConfiguration(final Configuration config) {        Assert.requireNonNull(config, "No Configuration was provided");        final Configuration prev = this.config;        config.addListener(this);        final ConcurrentMap
    
      map = config.getComponent(Configuration.CONTEXT_PROPERTIES);        try { // LOG4J2-719 network access may throw android.os.NetworkOnMainThreadException            map.putIfAbsent("hostName", NetUtils.getLocalHostname());        } catch (final Exception ex) {            LOGGER.debug("Ignoring {}, setting hostName to 'unknown'", ex.toString());            map.putIfAbsent("hostName", "unknown");        }        map.putIfAbsent("contextName", name);        config.start();        this.config = config;        updateLoggers();        if (prev != null) {            prev.removeListener(this);            prev.stop();        }        firePropertyChangeEvent(new PropertyChangeEvent(this, PROPERTY_CONFIG, prev, config));        try {            Server.reregisterMBeansAfterReconfigure();        } catch (final Throwable t) {            // LOG4J2-716: Android has no java.lang.management            LOGGER.error("Could not reconfigure JMX", t);        }        return prev;    }
    

这个方法最重要的步骤就是config.start,这才是真正做配置解析的

public void start() {        LOGGER.debug("Starting configuration {}", this);        this.setStarting();        pluginManager.collectPlugins(pluginPackages);        final PluginManager levelPlugins = new PluginManager(Level.CATEGORY);        levelPlugins.collectPlugins(pluginPackages);        final Map
    
     > plugins = levelPlugins.getPlugins();        if (plugins != null) {            for (final PluginType
      type : plugins.values()) {                try {                    // Cause the class to be initialized if it isn't already.                    Loader.initializeClass(type.getPluginClass().getName(), type.getPluginClass().getClassLoader());                } catch (final Exception e) {                    LOGGER.error("Unable to initialize {} due to {}", type.getPluginClass().getName(), e.getClass()                            .getSimpleName(), e);                }            }        }        setup();        setupAdvertisement();        doConfigure();        final Set
     
       alreadyStarted = new HashSet
      
       ();        for (final LoggerConfig logger : loggers.values()) {            logger.start();            alreadyStarted.add(logger);        }        for (final Appender appender : appenders.values()) {            appender.start();        }        if (!alreadyStarted.contains(root)) { // LOG4J2-392            root.start(); // LOG4J2-336        }        super.start();        LOGGER.debug("Started configuration {} OK.", this);    }
      
     
    

这里面有如下步骤：

1. 获取日志等级的插件
2. 初始化
3. 初始化Advertiser
4. 配置

先看一下初始化，也就是setup这个方法，setup是一个需要被复写的方法，我们以XMLConfiguration作为例子，

@Override    public void setup() {        if (rootElement == null) {            LOGGER.error("No logging configuration");            return;        }        constructHierarchy(rootNode, rootElement);        if (status.size() > 0) {            for (final Status s : status) {                LOGGER.error("Error processing element {}: {}", s.name, s.errorType);            }            return;        }        rootElement = null;    }

发现这里面有一个比较重要的方法constructHierarchy，跟进：

private void constructHierarchy(final Node node, final Element element) {        processAttributes(node, element);        final StringBuilder buffer = new StringBuilder();        final NodeList list = element.getChildNodes();        final List
    
      children = node.getChildren();        for (int i = 0; i < list.getLength(); i++) {            final org.w3c.dom.Node w3cNode = list.item(i);            if (w3cNode instanceof Element) {                final Element child = (Element) w3cNode;                final String name = getType(child);                final PluginType
      type = pluginManager.getPluginType(name);                final Node childNode = new Node(node, name, type);                constructHierarchy(childNode, child);                if (type == null) {                    final String value = childNode.getValue();                    if (!childNode.hasChildren() && value != null) {                        node.getAttributes().put(name, value);                    } else {                        status.add(new Status(name, element, ErrorType.CLASS_NOT_FOUND));                    }                } else {                    children.add(childNode);                }            } else if (w3cNode instanceof Text) {                final Text data = (Text) w3cNode;                buffer.append(data.getData());            }        }        final String text = buffer.toString().trim();        if (text.length() > 0 || (!node.hasChildren() && !node.isRoot())) {            node.setValue(text);        }    }
    

发现这个就是一个树遍历的过程。诚然，配置文件是以xml的形式给出的，xml的结构就是一个树形结构。回到start方法，跟进doConfiguration：

protected void doConfigure() {        if (rootNode.hasChildren() && rootNode.getChildren().get(0).getName().equalsIgnoreCase("Properties")) {            final Node first = rootNode.getChildren().get(0);            createConfiguration(first, null);            if (first.getObject() != null) {                subst.setVariableResolver((StrLookup) first.getObject());            }        } else {            final Map
    
      map = this.getComponent(CONTEXT_PROPERTIES);            final StrLookup lookup = map == null ? null : new MapLookup(map);            subst.setVariableResolver(new Interpolator(lookup, pluginPackages));        }        boolean setLoggers = false;        boolean setRoot = false;        for (final Node child : rootNode.getChildren()) {            if (child.getName().equalsIgnoreCase("Properties")) {                if (tempLookup == subst.getVariableResolver()) {                    LOGGER.error("Properties declaration must be the first element in the configuration");                }                continue;            }            createConfiguration(child, null);            if (child.getObject() == null) {                continue;            }            if (child.getName().equalsIgnoreCase("Appenders")) {                appenders = child.getObject();            } else if (child.isInstanceOf(Filter.class)) {                addFilter(child.getObject(Filter.class));            } else if (child.getName().equalsIgnoreCase("Loggers")) {                final Loggers l = child.getObject();                loggers = l.getMap();                setLoggers = true;                if (l.getRoot() != null) {                    root = l.getRoot();                    setRoot = true;                }            } else if (child.getName().equalsIgnoreCase("CustomLevels")) {                customLevels = child.getObject(CustomLevels.class).getCustomLevels();            } else if (child.isInstanceOf(CustomLevelConfig.class)) {                final List
     
       copy = new ArrayList
      
       (customLevels);                copy.add(child.getObject(CustomLevelConfig.class));                customLevels = copy;            } else {                LOGGER.error("Unknown object \"{}\" of type {} is ignored.", child.getName(),                        child.getObject().getClass().getName());            }        }        if (!setLoggers) {            LOGGER.warn("No Loggers were configured, using default. Is the Loggers element missing?");            setToDefault();            return;        } else if (!setRoot) {            LOGGER.warn("No Root logger was configured, creating default ERROR-level Root logger with Console appender");            setToDefault();            // return; // LOG4J2-219: creating default root=ok, but don't exclude configured Loggers        }        for (final Map.Entry
       
         entry : loggers.entrySet()) {            final LoggerConfig l = entry.getValue();            for (final AppenderRef ref : l.getAppenderRefs()) {                final Appender app = appenders.get(ref.getRef());                if (app != null) {                    l.addAppender(app, ref.getLevel(), ref.getFilter());                } else {                    LOGGER.error("Unable to locate appender {} for logger {}", ref.getRef(), l.getName());                }            }        }        setParents();    }
       
      
     
    

发现就是对刚刚获取的configuration进行解析，然后塞进正确的地方。回到start方法，可以看到昨晚配置之后就是开启logger和appender了。

异步

AsyncAppender

log4j2突出于其他日志的优势，异步日志实现。我们先从日志打印看进去。找到Logger，随便找一个log日志的方法。

public void debug(final Marker marker, final Message msg) {        logIfEnabled(FQCN, Level.DEBUG, marker, msg, msg != null ? msg.getThrowable() : null);    }

一路跟进

@PerformanceSensitive    // NOTE: This is a hot method. Current implementation compiles to 29 bytes of byte code.    // This is within the 35 byte MaxInlineSize threshold. Modify with care!    private void logMessageTrackRecursion(final String fqcn,                                          final Level level,                                          final Marker marker,                                          final Message msg,                                          final Throwable throwable) {        try {            incrementRecursionDepth(); // LOG4J2-1518, LOG4J2-2031            tryLogMessage(fqcn, level, marker, msg, throwable);        } finally {            decrementRecursionDepth();        }    }

可以看出这个在打日志之前做了调用次数的记录。跟进tryLogMessage，

@PerformanceSensitive    // NOTE: This is a hot method. Current implementation compiles to 26 bytes of byte code.    // This is within the 35 byte MaxInlineSize threshold. Modify with care!    private void tryLogMessage(final String fqcn,                               final Level level,                               final Marker marker,                               final Message msg,                               final Throwable throwable) {        try {            logMessage(fqcn, level, marker, msg, throwable);        } catch (final Exception e) {            // LOG4J2-1990 Log4j2 suppresses all exceptions that occur once application called the logger            handleLogMessageException(e, fqcn, msg);        }    }

继续跟进：

@Override    public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message,            final Throwable t) {        final Message msg = message == null ? new SimpleMessage(Strings.EMPTY) : message;        final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();        strategy.log(this, getName(), fqcn, marker, level, msg, t);    }

这里可以看到在实际打日志的时候，会从config中获取打日志的策略，跟踪ReliabilityStrategy的创建，发现默认的实现类为DefaultReliabilityStrategy，跟进看实际打日志的方法

@Override    public void log(final Supplier
    
      reconfigured, final String loggerName, final String fqcn, final Marker marker, final Level level,            final Message data, final Throwable t) {        loggerConfig.log(loggerName, fqcn, marker, level, data, t);    }
    

这里实际打日志的方法居然是交给一个config去实现的。。。感觉有点奇怪。。跟进看看

@PerformanceSensitive("allocation")    public void log(final String loggerName, final String fqcn, final Marker marker, final Level level,            final Message data, final Throwable t) {        List
    
      props = null;        if (!propertiesRequireLookup) {            props = properties;        } else {            if (properties != null) {                props = new ArrayList<>(properties.size());                final LogEvent event = Log4jLogEvent.newBuilder()                        .setMessage(data)                        .setMarker(marker)                        .setLevel(level)                        .setLoggerName(loggerName)                        .setLoggerFqcn(fqcn)                        .setThrown(t)                        .build();                for (int i = 0; i < properties.size(); i++) {                    final Property prop = properties.get(i);                    final String value = prop.isValueNeedsLookup() // since LOG4J2-1575                            ? config.getStrSubstitutor().replace(event, prop.getValue()) //                            : prop.getValue();                    props.add(Property.createProperty(prop.getName(), value));                }            }        }        final LogEvent logEvent = logEventFactory.createEvent(loggerName, marker, fqcn, level, data, props, t);        try {            log(logEvent, LoggerConfigPredicate.ALL);        } finally {            // LOG4J2-1583 prevent scrambled logs when logging calls are nested (logging in toString())            ReusableLogEventFactory.release(logEvent);        }    }
    

可以清楚的看到try之前是在创建LogEvent，try里面做的才是真正的log（好tm累），一路跟进。

private void processLogEvent(final LogEvent event, LoggerConfigPredicate predicate) {        event.setIncludeLocation(isIncludeLocation());        if (predicate.allow(this)) {            callAppenders(event);        }        logParent(event, predicate);    }

接下来就是callAppender了，我们直接开始看AsyncAppender的append方法：

/**     * Actual writing occurs here.     *     * @param logEvent The LogEvent.     */    @Override    public void append(final LogEvent logEvent) {        if (!isStarted()) {            throw new IllegalStateException("AsyncAppender " + getName() + " is not active");        }        final Log4jLogEvent memento = Log4jLogEvent.createMemento(logEvent, includeLocation);        InternalAsyncUtil.makeMessageImmutable(logEvent.getMessage());        if (!transfer(memento)) {            if (blocking) {                if (AbstractLogger.getRecursionDepth() > 1) { // LOG4J2-1518, LOG4J2-2031                    // If queue is full AND we are in a recursive call, call appender directly to prevent deadlock                    AsyncQueueFullMessageUtil.logWarningToStatusLogger();                    logMessageInCurrentThread(logEvent);                } else {                    // delegate to the event router (which may discard, enqueue and block, or log in current thread)                    final EventRoute route = asyncQueueFullPolicy.getRoute(thread.getId(), memento.getLevel());                    route.logMessage(this, memento);                }            } else {                error("Appender " + getName() + " is unable to write primary appenders. queue is full");                logToErrorAppenderIfNecessary(false, memento);            }        }    }

这里主要的步骤就是：

1. 生成logEvent
2. 将logEvent放入BlockingQueue，就是transfer方法
3. 如果BlockingQueue满了则启用相应的策略

同样的，这里也有一个线程用来做异步消费的事情

private class AsyncThread extends Log4jThread {        private volatile boolean shutdown = false;        private final List
    
      appenders;        private final BlockingQueue
     
       queue;        public AsyncThread(final List
      
        appenders, final BlockingQueue
       
         queue) {            super("AsyncAppender-" + THREAD_SEQUENCE.getAndIncrement());            this.appenders = appenders;            this.queue = queue;            setDaemon(true);        }        @Override        public void run() {            while (!shutdown) {                LogEvent event;                try {                    event = queue.take();                    if (event == SHUTDOWN_LOG_EVENT) {                        shutdown = true;                        continue;                    }                } catch (final InterruptedException ex) {                    break; // LOG4J2-830                }                event.setEndOfBatch(queue.isEmpty());                final boolean success = callAppenders(event);                if (!success && errorAppender != null) {                    try {                        errorAppender.callAppender(event);                    } catch (final Exception ex) {                        // Silently accept the error.                    }                }            }            // Process any remaining items in the queue.            LOGGER.trace("AsyncAppender.AsyncThread shutting down. Processing remaining {} queue events.",                queue.size());            int count = 0;            int ignored = 0;            while (!queue.isEmpty()) {                try {                    final LogEvent event = queue.take();                    if (event instanceof Log4jLogEvent) {                        final Log4jLogEvent logEvent = (Log4jLogEvent) event;                        logEvent.setEndOfBatch(queue.isEmpty());                        callAppenders(logEvent);                        count++;                    } else {                        ignored++;                        LOGGER.trace("Ignoring event of class {}", event.getClass().getName());                    }                } catch (final InterruptedException ex) {                    // May have been interrupted to shut down.                    // Here we ignore interrupts and try to process all remaining events.                }            }            LOGGER.trace("AsyncAppender.AsyncThread stopped. Queue has {} events remaining. "                + "Processed {} and ignored {} events since shutdown started.", queue.size(), count, ignored);        }        /**         * Calls {@link AppenderControl#callAppender(LogEvent) callAppender} on all registered {@code AppenderControl}         * objects, and returns {@code true} if at least one appender call was successful, {@code false} otherwise. Any         * exceptions are silently ignored.         *         * @param event the event to forward to the registered appenders         * @return {@code true} if at least one appender call succeeded, {@code false} otherwise         */        boolean callAppenders(final LogEvent event) {            boolean success = false;            for (final AppenderControl control : appenders) {                try {                    control.callAppender(event);                    success = true;                } catch (final Exception ex) {                    // If no appender is successful the error appender will get it.                }            }            return success;        }        public void shutdown() {            shutdown = true;            if (queue.isEmpty()) {                queue.offer(SHUTDOWN_LOG_EVENT);            }            if (getState() == State.TIMED_WAITING || getState() == State.WAITING) {                this.interrupt(); // LOG4J2-1422: if underlying appender is stuck in wait/sleep/join/park call            }        }    }
       
      
     
    

直接看run方法：

1. 阻塞获取logEvent
2. 将logEvent分发出去
3. 如果线程要退出了，将blockingQueue里面的event消费完在退出。

AsyncLogger

直接从AsyncLogger的logMessage看进去：

public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message,            final Throwable thrown) {        if (loggerDisruptor.isUseThreadLocals()) {            logWithThreadLocalTranslator(fqcn, level, marker, message, thrown);        } else {            // LOG4J2-1172: avoid storing non-JDK classes in ThreadLocals to avoid memory leaks in web apps            logWithVarargTranslator(fqcn, level, marker, message, thrown);        }    }

跟进logWithThreadLocalTranslator，

private void logWithThreadLocalTranslator(final String fqcn, final Level level, final Marker marker,            final Message message, final Throwable thrown) {        // Implementation note: this method is tuned for performance. MODIFY WITH CARE!        final RingBufferLogEventTranslator translator = getCachedTranslator();        initTranslator(translator, fqcn, level, marker, message, thrown);        initTranslatorThreadValues(translator);        publish(translator);    }

这里的逻辑很简单，就是将日志相关的信息转换成RingBufferLogEvent（RingBuffer是Disruptor的无所队列），然后将其发布到RingBuffer中。发布到RingBuffer中，那肯定也有消费逻辑。这时候有两种方式可以找到这个消费的逻辑。

• 找disruptor被使用的地方，然后查看，但是这样做会很容易迷惑
• 按照Log4j2的尿性，这种Logger都有对应的start方法，我们可以从start方法入手寻找

在start方法中，我们找到了一段代码：

final RingBufferLogEventHandler[] handlers = {new RingBufferLogEventHandler()};        disruptor.handleEventsWith(handlers);

直接看看这个RingBufferLogEventHandler的实现：

public class RingBufferLogEventHandler implements        SequenceReportingEventHandler
    
     , LifecycleAware {    private static final int NOTIFY_PROGRESS_THRESHOLD = 50;    private Sequence sequenceCallback;    private int counter;    private long threadId = -1;    @Override    public void setSequenceCallback(final Sequence sequenceCallback) {        this.sequenceCallback = sequenceCallback;    }    @Override    public void onEvent(final RingBufferLogEvent event, final long sequence,            final boolean endOfBatch) throws Exception {        event.execute(endOfBatch);        event.clear();        // notify the BatchEventProcessor that the sequence has progressed.        // Without this callback the sequence would not be progressed        // until the batch has completely finished.        if (++counter > NOTIFY_PROGRESS_THRESHOLD) {            sequenceCallback.set(sequence);            counter = 0;        }    }    /**     * Returns the thread ID of the background consumer thread, or {@code -1} if the background thread has not started     * yet.     * @return the thread ID of the background consumer thread, or {@code -1}     */    public long getThreadId() {        return threadId;    }    @Override    public void onStart() {        threadId = Thread.currentThread().getId();    }    @Override    public void onShutdown() {    }}
    

顺着接口找上去，发现一个接口：

/** * Callback interface to be implemented for processing events as they become available in the {@link RingBuffer} * * @param 
    
      event implementation storing the data for sharing during exchange or parallel coordination of an event. * @see BatchEventProcessor#setExceptionHandler(ExceptionHandler) if you want to handle exceptions propagated out of the handler. */public interface EventHandler
     
      {    /**     * Called when a publisher has published an event to the {@link RingBuffer}     *     * @param event      published to the {@link RingBuffer}     * @param sequence   of the event being processed     * @param endOfBatch flag to indicate if this is the last event in a batch from the {@link RingBuffer}     * @throws Exception if the EventHandler would like the exception handled further up the chain.     */    void onEvent(T event, long sequence, boolean endOfBatch) throws Exception;}
     
    

通过注释可以发现，这个onEvent就是处理逻辑，回到RingBufferLogEventHandler的onEvent方法，发现里面有一个execute方法，跟进：

public void execute(final boolean endOfBatch) {        this.endOfBatch = endOfBatch;        asyncLogger.actualAsyncLog(this);    }

这个方法就是实际打日志了，AsyncLogger看起来还是比较简单的，只是使用了一个Disruptor。

插件化

之前在很多代码里面都可以看到

final PluginManager manager = new PluginManager(CATEGORY);manager.collectPlugins(pluginPackages);

其实整个log4j2为了获得更好的扩展性，将自己的很多组件都做成了插件，然后在配置的时候去加载plugin。

跟进collectPlugins。

public void collectPlugins(final List
    
      packages) {        final String categoryLowerCase = category.toLowerCase();        final Map
     
      > newPlugins = new LinkedHashMap<>();        // First, iterate the Log4j2Plugin.dat files found in the main CLASSPATH        Map
      
       >> builtInPlugins = PluginRegistry.getInstance().loadFromMainClassLoader();        if (builtInPlugins.isEmpty()) {            // If we didn't find any plugins above, someone must have messed with the log4j-core.jar.            // Search the standard package in the hopes we can find our core plugins.            builtInPlugins = PluginRegistry.getInstance().loadFromPackage(LOG4J_PACKAGES);        }        mergeByName(newPlugins, builtInPlugins.get(categoryLowerCase));        // Next, iterate any Log4j2Plugin.dat files from OSGi Bundles        for (final Map
       
        >> pluginsByCategory : PluginRegistry.getInstance().getPluginsByCategoryByBundleId().values()) {            mergeByName(newPlugins, pluginsByCategory.get(categoryLowerCase));        }        // Next iterate any packages passed to the static addPackage method.        for (final String pkg : PACKAGES) {            mergeByName(newPlugins, PluginRegistry.getInstance().loadFromPackage(pkg).get(categoryLowerCase));        }        // Finally iterate any packages provided in the configuration (note these can be changed at runtime).        if (packages != null) {            for (final String pkg : packages) {                mergeByName(newPlugins, PluginRegistry.getInstance().loadFromPackage(pkg).get(categoryLowerCase));            }        }        LOGGER.debug("PluginManager '{}' found {} plugins", category, newPlugins.size());        plugins = newPlugins;    }
       
      
     
    

处理逻辑如下：

1. 从Log4j2Plugin.dat中加载所有的内置的plugin
2. 然后将OSGi Bundles中的Log4j2Plugin.dat中的plugin加载进来
3. 再加载传入的package路径中的plugin
4. 最后加载配置中的plugin

逻辑还是比较简单的，但是我在看源码的时候发现了一个很有意思的东西，就是在加载log4j2 core插件的时候，也就是

PluginRegistry.getInstance().loadFromMainClassLoader()

这个方法，跟进到decodeCacheFiles：

private Map
    
     >> decodeCacheFiles(final ClassLoader loader) {        final long startTime = System.nanoTime();        final PluginCache cache = new PluginCache();        try {            final Enumeration
     
       resources = loader.getResources(PluginProcessor.PLUGIN_CACHE_FILE);            if (resources == null) {                LOGGER.info("Plugin preloads not available from class loader {}", loader);            } else {                cache.loadCacheFiles(resources);            }        } catch (final IOException ioe) {            LOGGER.warn("Unable to preload plugins", ioe);        }        final Map
      
       >> newPluginsByCategory = new HashMap<>();        int pluginCount = 0;        for (final Map.Entry
       
        > outer : cache.getAllCategories().entrySet()) {            final String categoryLowerCase = outer.getKey();            final List
        
         > types = new ArrayList<>(outer.getValue().size());            newPluginsByCategory.put(categoryLowerCase, types);            for (final Map.Entry
         
           inner : outer.getValue().entrySet()) { final PluginEntry entry = inner.getValue(); final String className = entry.getClassName(); try { final Class
           clazz = loader.loadClass(className); final PluginType
           type = new PluginType<>(entry, clazz, entry.getName()); types.add(type); ++pluginCount; } catch (final ClassNotFoundException e) { LOGGER.info("Plugin [{}] could not be loaded due to missing classes.", className, e); } catch (final LinkageError e) { LOGGER.info("Plugin [{}] could not be loaded due to linkage error.", className, e); } } } final long endTime = System.nanoTime(); final DecimalFormat numFormat = new DecimalFormat("#0.000000"); final double seconds = (endTime - startTime) * 1e-9; LOGGER.debug("Took {} seconds to load {} plugins from {}", numFormat.format(seconds), pluginCount, loader); return newPluginsByCategory; }
         
        
       
      
     
    

可以发现加载时候是从一个文件（PLUGIN_CACHE_FILE）获取所有要获取的plugin。看到这里的时候我有一个疑惑就是，为什么不用反射的方式直接去扫描，而是要从文件中加载进来，而且文件是写死的，很不容易扩展啊。然后我找了一下PLUGIN_CACHE_FILE这个静态变量的用处，发现了PluginProcessor这个类，这里用到了。

/** * Annotation processor for pre-scanning Log4j 2 plugins. */@SupportedAnnotationTypes("org.apache.logging.log4j.core.config.plugins.*")public class PluginProcessor extends AbstractProcessor {    // TODO: this could be made more abstract to allow for compile-time and run-time plugin processing    /**     * The location of the plugin cache data file. This file is written to by this processor, and read from by     * {@link org.apache.logging.log4j.core.config.plugins.util.PluginManager}.     */    public static final String PLUGIN_CACHE_FILE =            "META-INF/org/apache/logging/log4j/core/config/plugins/Log4j2Plugins.dat";    private final PluginCache pluginCache = new PluginCache();    @Override    public boolean process(final Set
     annotations, final RoundEnvironment roundEnv) {        System.out.println("Processing annotations");        try {            final Set
     elements = roundEnv.getElementsAnnotatedWith(Plugin.class);            if (elements.isEmpty()) {                System.out.println("No elements to process");                return false;            }            collectPlugins(elements);            writeCacheFile(elements.toArray(new Element[elements.size()]));            System.out.println("Annotations processed");            return true;        } catch (final IOException e) {            e.printStackTrace();            error(e.getMessage());            return false;        } catch (final Exception ex) {            ex.printStackTrace();            error(ex.getMessage());            return false;        }    }}

（不太重要的方法省略）

我们可以看到在process方法中，PluginProcessor会先收集所有的Plugin，然后在写入文件。这样做的好处就是可以省去反射时候的开销。

然后我又看了一下Plugin这个注解，发现它的RetentionPolicy是RUNTIME，一般来说PluginProcessor是搭配RetentionPolicy.SOURCE，CLASS使用的，而且既然你把自己的Plugin扫描之后写在文件中了，RetentionPolicy就没有必要是RUNTIME了吧，这个是一个很奇怪的地方。

小结

总算是把Log4j2的代码看完了，发现它的设计理念很值得借鉴，为了灵活性，所有的东西都设计成插件式。互联网技术日益发展，各种中间件层出不穷，而作为工程师的我们更需要做的是去思考代码与代码之间的关系，毫无疑问的是，解耦是最具有美感的关系。

作者：netflix

​

本文为云栖社区原创内容，未经允许不得转载。