27
探索Java日志的奥秘：底层日志系统-log4j2 原 荐
source link: https://my.oschina.net/yunqi/blog/3034578?amp%3Butm_medium=referral
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
前言
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());
}
} 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();
}
}
}
这段静态代码段主要分为下面的几个步骤：
- 首先根据特定配置文件的配置信息获取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);
}
}
}
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());
}
} 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
原文链接
本文为云栖社区原创内容，未经允许不得转载。
Recommend
About Joyk
Aggregate valuable and interesting links.
Joyk means Joy of geeK