log和ex是什么关系

前言

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.u (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 = Pro(); final String factoryClassName = managerPro(FACTORY_PROPERTY_NAME); if (factoryClassName != null) { try { factory = LoaderU(factoryClassName, LoggerCon); } 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<Integer, LoggerContextFactory> 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 ()) { for (final Provider provider : ProviderU()) { final Class<? extends LoggerContextFactory> factoryClass = (); if (factoryClass != null) { try { (), ()); } catch (final Exception e) { LOGGER.error("Unable to create class {} specified in provider URL {}", (), provider .getUrl(), e); } } } if ()) { 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 () == 1) { factory = ()); } else { final StringBuilder sb = new StringBuilder("Multiple logging implementations found: \n"); for (final Map.Entry<Integer, LoggerContextFactory> entry : ()) { ("Factory: ").append().getClass().getName()); (", Weighting: ").append()).append('\n'); } factory = ()); ("Using factory: ").append().getName()); LOGGER.warn()); } } 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 = Pro(); final String factoryClassName = managerPro(FACTORY_PROPERTY_NAME); if (factoryClassName != null) { try { factory = LoaderU(factoryClassName, LoggerCon); } 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.com”通过配置项”log4j2.loggerContextFactory”来获取LoggerContextFactory，如果用户做了对应的配置，通过newCheckedInstanceOf方法实例化LoggerContextFactory的对象，最终的实现方式为：

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

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

通过Provider实例化LoggerContextFactory对象

代码：

if (factory == null) { final SortedMap<Integer, LoggerContextFactory> 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 ()) { for (final Provider provider : ProviderU()) { final Class<? extends LoggerContextFactory> factoryClass = (); if (factoryClass != null) { try { (), ()); } catch (final Exception e) { LOGGER.error("Unable to create class {} specified in provider URL {}", (), provider .getUrl(), e); } } } if ()) { 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 () == 1) { factory = ()); } else { final StringBuilder sb = new StringBuilder("Multiple logging implementations found: \n"); for (final Map.Entry<Integer, LoggerContextFactory> entry : ()) { ("Factory: ").append().getClass().getName()); (", Weighting: ").append()).append('\n'); } factory = ()); ("Using factory: ").append().getName()); LOGGER.warn()); } } 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); T().interrupt(); } finally { STARTUP_LOCK.unlock(); } } }

再看构造方法：

private ProviderUtil() { for (final LoaderU resource : LoaderU(PROVIDER_RESOURCE)) { loadProvider(), re()); } }

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

LoggerContextFactory = org.a Log4jAPIVersion = 2.1.0 FactoryPriority= 10

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

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

lock 与 lockInterruptibly比较区别在于：

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

lockInterruptibly 优先考虑响应中断，而不是响应锁的普通获取或重入获取。

Reen允许在等待时由其它线程调用等待线程的

T 方法来中断等待线程的等待而直接返回，这时不用获取锁，而会抛出一个InterruptedException。 Reen方法不允许T中断,即使检测到T,一样会继续尝试获取锁，失败则继续休眠。只是在最后获取锁成功后再把当前线程置为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 ()) { 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 () == 1) { factory = ()); } else { final StringBuilder sb = new StringBuilder("Multiple logging implementations found: \n"); for (final Map.Entry<Integer, LoggerContextFactory> entry : ()) { ("Factory: ").append().getClass().getName()); (", Weighting: ").append()).append('\n'); } factory = ()); ("Using factory: ").append().getName()); LOGGER.warn()); }

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

配置

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

Logger logger = logManager.getLogger)

跟进getLogger方法：

public static Logger getLogger(final Class<?> clazz) { final Class<?> cls = callerClass(clazz); return getContex(), false).getLogger(toLoggerName(cls)); }

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

public static LoggerContext getContext(final ClassLoader loader, final boolean currentContext) { try { return (FQCN, loader, null, currentContext); } catch (final IllegalStateException ex) { LOGGER.warn() + " 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 = (fqcn, loader, currentContext); if (externalContext != null && c() == null) { c(externalContext); } if () == Li) { c(); } return ctx; }

直接看start：

public void start() { LOGGER.debug("Starting LoggerContext[name={}, {}]...", getName(), this); if (Pro().getBooleanProperty("log4j.LoggerCon;, false)) { LOGGER.debug("Stack trace to locate invoker", new Exception("Not a real error, showing stack trace to locate invoker")); } if ()) { try { if () || ()) { (); reconfigure(); if ()) { setUpShutdownHook(); } (); } } finally { con(); } } LOGGER.debug("LoggerContext[name={}, {}] started OK.", getName(), this); }

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

private void reconfigure(final URI configURI) { final ClassLoader cl = Cla(externalContext) ? (ClassLoader) externalContext : null; LOGGER.debug("Reconfiguration started for context[name={}] at URI {} ({}) with optional ClassLoader: {}", contextName, configURI, this, cl); final Configuration instance = Con().getConfiguration(this, contextName, configURI, cl); if (instance == null) { LOGGER.error("Reconfiguration failed: No configuration found for '{}' at '{}' in '{}'", contextName, configURI, cl); } else { setConfiguration(instance); /* * in(); Configuration old = setConfiguration(instance); updateLoggers(); if (old != null) { * old.stop(); } */ final String location = configuration == null ? "?" : S()); 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<ConfigurationFactory> list = new ArrayList<ConfigurationFactory>(); final String factoryClass = Pro().getStringProperty(CONFIGURATION_FACTORY_PROPERTY); if (factoryClass != null) { addFactory(list, factoryClass); } final PluginManager manager = new PluginManager(CATEGORY); manager.collectPlugins(); final Map<String, PluginType<?>> plugins = manager.getPlugins(); final List<Class<? extends ConfigurationFactory>> ordered = new ArrayList<Class<? extends ConfigurationFactory>>()); for (final PluginType<?> type : ()) { try { ordered.add().asSubcla)); } catch (final Exception ex) { LOGGER.warn("Unable to add class {}", (), ex); } } Collec(ordered, OrderCom()); for (final Class<? extends ConfigurationFactory> clazz : ordered) { addFactory(list, clazz); } // see above comments about double-checked locking //noinspection NonThreadSafeLazyInitialization factories = Collec(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 = ( Pro().getStringProperty(CONFIGURATION_FILE_PROPERTY)); if (config != null) { ConfigurationSource source = null; try { source = getInputFromUri(config)); } catch (final Exception ex) { // Ignore the error and try as a String. LOGGER.catching, ex); } if (source == null) { final ClassLoader loader = LoaderU(); source = getInputFromString(config, loader); } if (source != null) { for (final ConfigurationFactory factory : factories) { final String[] types = (); if (types != null) { for (final String type : types) { if ("*") || con(type)) { final Configuration c = (source); if (c != null) { return c; } } } } } } } } else { for (final ConfigurationFactory factory : factories) { final String[] types = (); if (types != null) { for (final String type : types) { if ("*") || con().endsWith(type)) { final Configuration config = (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) { A(config, "No Configuration was provided"); final Configuration prev = ; con(this); final ConcurrentMap<String, String> map = con); try { // LOG4J2-719 network access may throw android.os.NetworkOnMainThreadException map.putIfAbsent("hostName", Ne()); } catch (final Exception ex) { LOGGER.debug("Ignoring {}, setting hostName to 'unknown'", ex.toString()); map.putIfAbsent("hostName", "unknown"); } map.putIfAbsent("contextName", name); con(); = config; updateLoggers(); if (prev != null) { (this); (); } 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; }

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

public void start() { LOGGER.debug("Starting configuration {}", this); (); (pluginPackages); final PluginManager levelPlugins = new PluginManager); levelPlugins.collectPlugins(pluginPackages); final Map<String, PluginType<?>> plugins = levelPlugins.getPlugins(); if (plugins != null) { for (final PluginType<?> type : ()) { try { // Cause the class to be initialized if it isn't already. Loader.initializeClass().getName(), ().getClassLoader()); } catch (final Exception e) { LOGGER.error("Unable to initialize {} due to {}", ().getName(), e.getClass() .getSimpleName(), e); } } } setup(); setupAdvertisement(); doConfigure(); final Set<LoggerConfig> alreadyStarted = new HashSet<LoggerConfig>(); for (final LoggerConfig logger : loggers.values()) { logger.start(); alreadyS(logger); } for (final Appender appender : a()) { a(); } if (!alreadyS(root)) { // LOG4J2-392 root.start(); // LOG4J2-336 } (); 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 () > 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<Node> children = node.getChildren(); for (int i = 0; i < li(); i++) { final org.w3c.dom.Node w3cNode = li(i); if (w3cNode instanceof Element) { final Element child = (Element) w3cNode; final String name = getType(child); final PluginType<?> type = (name); final Node childNode = new Node(node, name, type); constructHierarchy(childNode, child); if (type == null) { final String value = c(); if (!c() && value != null) { node.getAttributes().put(name, value); } else { (new Status(name, element, ErrorTy)); } } else { c(childNode); } } else if (w3cNode instanceof Text) { final Text data = (Text) w3cNode; bu()); } } final String text = bu().trim(); if () > 0 || (!node.hasChildren() && !node.isRoot())) { node.setValue(text); } }

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

protected void doConfigure() { if () && roo().get(0).getName().equalsIgnoreCase("Properties")) { final Node first = roo().get(0); createConfiguration(first, null); if () != null) { ((StrLookup) ()); } } else { final Map<String, String> map = (CONTEXT_PROPERTIES); final StrLookup lookup = map == null ? null : new MapLookup(map); (new Interpolator(lookup, pluginPackages)); } boolean setLoggers = false; boolean setRoot = false; for (final Node child : roo()) { if ().equalsIgnoreCase("Properties")) { if (tempLookup == ()) { LOGGER.error("Properties declaration must be the first element in the configuration"); } continue; } createConfiguration(child, null); if () == null) { continue; } if ().equalsIgnoreCase("Appenders")) { appenders = c(); } else if )) { addFilter)); } else if ().equalsIgnoreCase("Loggers")) { final Loggers l = c(); loggers = l.getMap(); setLoggers = true; if () != null) { root = l.getRoot(); setRoot = true; } } else if ().equalsIgnoreCase("CustomLevels")) { customLevels = c).getCustomLevels(); } else if )) { final List<CustomLevelConfig> copy = new ArrayList<CustomLevelConfig>(customLevels); co)); customLevels = copy; } else { LOGGER.error("Unknown object \"{}\" of type {} is ignored.", c(), c().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<String, LoggerConfig> entry : loggers.entrySet()) { final LoggerConfig l = en(); for (final AppenderRef ref : l.getAppenderRefs()) { final Appender app = a()); 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 ? m() : 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) : message; final ReliabilityStrategy strategy = (); (this, getName(), fqcn, marker, level, msg, t); }

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

@Override public void log(final Supplier<LoggerConfig> reconfigured, final String loggerName, final String fqcn, final Marker marker, final Level level, final Message data, final Throwable t) { loggerCon(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<Property> props = null; if (!propertiesRequireLookup) { props = properties; } else { if (properties != null) { props = new ArrayList<>()); final LogEvent event = Log4jLogEvent.newBuilder() .setMessage(data) .setMarker(marker) .setLevel(level) .setLoggerName(loggerName) .setLoggerFqcn(fqcn) .setThrown(t) .build(); for (int i = 0; i < (); i++) { final Property prop = (i); final String value = () // since LOG4J2-1575 ? con().replace(event, ()) // : (); (), value)); } } } final LogEvent logEvent = logEven(loggerName, marker, fqcn, level, data, props, t); try { log(logEvent, LoggerCon); } finally { // LOG4J2-1583 prevent scrambled logs when logging calls are nested (logging in toString()) Reu(logEvent); } }

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

private void processLogEvent(final LogEvent event, LoggerConfigPredicate predicate) { event.setIncludeLocation(isIncludeLocation()); if (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); In()); if (!transfer(memento)) { if (blocking) { if () > 1) { // LOG4J2-1518, LOG4J2-2031 // If queue is full AND we are in a recursive call, call appender directly to prevent deadlock A(); logMessageInCurrentThread(logEvent); } else { // delegate to the event router (which may discard, enqueue and block, or log in current thread) final EventRoute route = a(), memen()); rou(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<AppenderControl> appenders; private final BlockingQueue<LogEvent> queue; public AsyncThread(final List<AppenderControl> appenders, final BlockingQueue<LogEvent> queue) { super("AsyncAppender-" + THREAD_SEQUENCE.getAndIncrement()); = appenders; = 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.setEndOfBatc()); final boolean success = callAppenders(event); if (!success && errorAppender != null) { try { errorA(event); } catch (final Exception ex) { // Silently accept the error. } } } // Process any remaining items in the queue. LOGGER.trace("A 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.setEndOfBatc()); 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("A 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 { con(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.offer(SHUTDOWN_LOG_EVENT); } if (getState() == S || getState() == S) { (); // 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 ()) { 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()}; di(handlers);

直接看看这个RingBufferLogEventHandler的实现：

public class RingBufferLogEventHandler implements SequenceReportingEventHandler<RingBufferLogEvent>, 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) { = 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) { (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 = T().getId(); } @Override public void onShutdown() { } }

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

/** * Callback interface to be implemented for processing events as they become available in the {@link RingBuffer} * * @param <T> 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<T> { /** * 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) { = endOfBatch; a(this); }

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

插件化

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

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

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

跟进collectPlugins。

public void collectPlugins(final List<String> packages) { final String categoryLowerCase = ca(); final Map<String, PluginType<?>> newPlugins = new LinkedHashMap<>(); // First, iterate the Log4j2Plugin.dat files found in the main CLASSPATH Map<String, List<PluginType<?>>> builtInPlugins = PluginRegi().loadFromMainClassLoader(); if ()) { // 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 = PluginRegi().loadFromPackage(LOG4J_PACKAGES); } mergeByName(newPlugins, buil(categoryLowerCase)); // Next, iterate any Log4j2Plugin.dat files from OSGi Bundles for (final Map<String, List<PluginType<?>>> pluginsByCategory : PluginRegi().getPluginsByCategoryByBundleId().values()) { mergeByName(newPlugins, (categoryLowerCase)); } // Next iterate any packages passed to the static addPackage method. for (final String pkg : PACKAGES) { mergeByName(newPlugins, PluginRegi().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, PluginRegi().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插件的时候，也就是

PluginRegi().loadFromMainClassLoader()

这个方法，跟进到decodeCacheFiles：

private Map<String, List<PluginType<?>>> decodeCacheFiles(final ClassLoader loader) { final long startTime = Sy(); final PluginCache cache = new PluginCache(); try { final Enumeration<URL> resources = loader.getResource); if (resources == null) { LOGGER.info("Plugin preloads not available from class loader {}", loader); } else { cac(resources); } } catch (final IOException ioe) { LOGGER.warn("Unable to preload plugins", ioe); } final Map<String, List<PluginType<?>>> newPluginsByCategory = new HashMap<>(); int pluginCount = 0; for (final Map.Entry<String, Map<String, PluginEntry>> outer : cac().entrySet()) { final String categoryLowerCase = ou(); final List<PluginType<?>> types = new ArrayList<>().size()); newPlugin(categoryLowerCase, types); for (final Map.Entry<String, PluginEntry> inner : ou().entrySet()) { final PluginEntry entry = inner.getValue(); final String className = en(); try { final Class<?> clazz = loader.loadClass(className); final PluginType<?> type = new PluginType<>(entry, clazz, en()); (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 = Sy(); 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.a.*") 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.a.util.PluginManager}. */ public static final String PLUGIN_CACHE_FILE = "META-INF/org/apache/logging/log4j/core/config/plugin;; private final PluginCache pluginCache = new PluginCache(); @Override public boolean process(final Set<? extends TypeElement> annotations, final RoundEnvironment roundEnv) { Sy("Processing annotations"); try { final Set<? extends Element> elements = roundEnv.getElementsAnnotatedWi); if ()) { Sy("No elements to process"); return false; } collectPlugins(elements); writeCacheFile(new Element[elemen()])); Sy("Annotations processed"); return true; } catch (final IOException e) { e.printStackTrace(); error()); return false; } catch (final Exception ex) { ex.printStackTrace(); error()); return false; } } }

（不太重要的方法省略）

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

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

小结

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

作者：netflix