探索Java日誌的奧祕：底層日誌系統-log4j2
前言
log4j2是apache在log4j的基礎上，參考logback架構實現的一套新的日誌系統（我感受是apache懼怕logback了）。
log4j2的官方文檔上寫着一些它的優勢：html
- 在擁有所有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類圖：java
此次從四個地方去探索源碼：啓動，配置，異步，插件化node
源碼探索
啓動
log4j2的關鍵組件android
- LogManager
根據配置指定LogContexFactory，初始化對應的LoggerContextweb
- LoggerContext
一、解析配置文件，解析爲對應的java對象。
二、經過LoggerRegisty緩存Logger配置
三、Configuration配置信息
四、start方法解析配置文件，轉化爲對應的java對象
五、經過getLogger獲取logger對象正則表達式
- Logger
LogManaer
該組件是Log4J啓動的入口，後續的LoggerContext以及Logger都是經過調用LogManager的靜態方法得到。咱們可使用下面的代碼獲取Loggerapache
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的代碼看完了，發現它的設計理念很值得借鑑，爲了靈活性，全部的東西都設計成插件式。互聯網技術日益發展，各類中間件層出不窮，而做爲工程師的咱們更須要作的是去思考代碼與代碼之間的關係，毫無疑問的是，解耦是最具備美感的關係。
原文連接 本文爲雲棲社區原創內容，未經容許不得轉載。
相關文章
- 1. 探索Java日誌的奧祕：底層日誌系統-log4j2
- 2. 探索java世界中的日誌奧祕
- 3. Java日誌體系（六）log4j2
- 4. iptables日誌探祕
- 5. 日誌之log4j2
- 6. Java日誌框架與日誌系統
- 7. 日誌-syslog系統日誌
- 8. JAVA日誌系統
- 9. log4j2日誌配置
- 10. log4j2日誌簡介
- 更多相關文章...
- • SQLite 日期 & 時間 - SQLite教程
- • 系統定義的TypeHandler - MyBatis教程
- • Docker容器實戰(七) - 容器眼光下的文件系統
- • ☆基於Java Instrument的Agent實現
相關標籤/搜索
每日一句
-
每一个你不满意的现在，都有一个你没有努力的曾经。
歡迎關注本站公眾號,獲取更多信息
相關文章
- 1. 探索Java日誌的奧祕：底層日誌系統-log4j2
- 2. 探索java世界中的日誌奧祕
- 3. Java日誌體系（六）log4j2
- 4. iptables日誌探祕
- 5. 日誌之log4j2
- 6. Java日誌框架與日誌系統
- 7. 日誌-syslog系統日誌
- 8. JAVA日誌系統
- 9. log4j2日誌配置
- 10. log4j2日誌簡介