探索Java日志的奥秘：底层日志系统-log4j2

jiezi

6 年前

前言
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<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 (ProviderUtil.hasProviders()) {
for (final Provider provider : ProviderUtil.getProviders()) {
final Class<? extends LoggerContextFactory> 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<Integer, LoggerContextFactory> 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());

首先根据特定配置文件的配置信息获取 loggerContextFactory
如果没有找到对应的 Factory 的实现类则通过 ProviderUtil 中的 getProviders() 方法载入 providers，随后通过 provider 的 loadLoggerContextFactory 方法载入 LoggerContextFactory 的实现类
如果 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> 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 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<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 (ProviderUtil.hasProviders()) {
for (final Provider provider : ProviderUtil.getProviders()) {
final Class<? extends LoggerContextFactory> 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);
}
}
}

}
} 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.Log4jContextFactory
Log4jAPIVersion = 2.1.0
FactoryPriority= 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<Integer, LoggerContextFactory> 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<ConfigurationFactory> list = new ArrayList<ConfigurationFactory>();
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<String, PluginType<?>> plugins = manager.getPlugins();
final List<Class<? extends ConfigurationFactory>> ordered =
new ArrayList<Class<? extends ConfigurationFactory>>(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<? extends ConfigurationFactory> 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<String, String> 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<String, PluginType<?>> 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<LoggerConfig> alreadyStarted = new HashSet<LoggerConfig>();
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);
}
这里面有如下步骤：

获取日志等级的插件
初始化
初始化 Advertiser
配置

先看一下初始化，也就是 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<Node> 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<String, String> 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<CustomLevelConfig> copy = new ArrayList<CustomLevelConfig>(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<String, LoggerConfig> 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<LoggerConfig> 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<Property> 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);
}
}
}
这里主要的步骤就是：

生成 logEvent
将 logEvent 放入 BlockingQueue，就是 transfer 方法
如果 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());
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 方法：

阻塞获取 logEvent
将 logEvent 分发出去
如果线程要退出了，将 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<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) {
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 <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) {
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<String> packages) {
final String categoryLowerCase = category.toLowerCase();
final Map<String, PluginType<?>> newPlugins = new LinkedHashMap<>();

// First, iterate the Log4j2Plugin.dat files found in the main CLASSPATH
Map<String, List<PluginType<?>>> 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<String, List<PluginType<?>>> 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;
}
处理逻辑如下：

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

逻辑还是比较简单的，但是我在看源码的时候发现了一个很有意思的东西，就是在加载 log4j2 core 插件的时候，也就是
PluginRegistry.getInstance().loadFromMainClassLoader()
这个方法，跟进到 decodeCacheFiles：
private Map<String, List<PluginType<?>>> decodeCacheFiles(final ClassLoader loader) {
final long startTime = System.nanoTime();
final PluginCache cache = new PluginCache();
try {
final Enumeration<URL> 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<String, List<PluginType<?>>> newPluginsByCategory = new HashMap<>();
int pluginCount = 0;
for (final Map.Entry<String, Map<String, PluginEntry>> outer : cache.getAllCategories().entrySet()) {
final String categoryLowerCase = outer.getKey();
final List<PluginType<?>> types = new ArrayList<>(outer.getValue().size());
newPluginsByCategory.put(categoryLowerCase, types);
for (final Map.Entry<String, PluginEntry> 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<? extends TypeElement> annotations, final RoundEnvironment roundEnv) {
System.out.println(“Processing annotations”);
try {
final Set<? extends Element> 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 阅读原文
本文为云栖社区原创内容，未经允许不得转载。