Log4j 2 Understanding the underlying concepts of the log system
In this article, we'll break down the source code of ** Log4j ** 2, a new log system built on Apache Log4j, and dig deeper into the underlying concepts.
- This blog is a translation from the English version. You can check the original from here. We use some machine translation. We would appreciate it if you could point out any translation errors. *
Overview
Log4j 2 is a brand new logging system built on top of Apache Log4j with reference to the Logback architecture. I think this is because Log4j is basically deprecated by Logback.
See the official documentation Apache Log4j 2 for the benefits of Log4j 2.
--Log4j 2 provides many improvements available in Logback while fixing some of the issues inherent in the Logback architecture. --API Separation: The Log4j 2 API can be used with a Log4j 2 implementation, but it can also be used before other logging implementations such as Logback (though no one will do it). The façade. --Performance Improvements: Log4j 2 includes a next-generation asynchronous logger based on the LMAX Disruptor library. In multithreaded scenarios, asynchronous loggers have 18x higher throughput and orders of magnitude lower latency than Log4j and Logback. --Multiple API support: Log4j 2 provides support for Log4j 1.2, SLF4J, Commons Logging and the java.util.logging (JUL) API. --Avoid lock-in: Applications coded into the Log4j 2 API always have the option to use any SLF4J compliant library as their logger implementation, using the log4j-to-slf4j adapter. ..
--Automatic reloading of settings: Similar to Logback, Log4j 2 can automatically reload settings when it changes. Unlike Logback, it does this without losing log events during the reconfiguration. --Advanced Filtering: Like Logback, Log4j 2 supports filtering based on contextual data, markers, regular expressions, and other components of log events. --Plug-in architecture: Log4j uses plug-in patterns to configure components. So you don't have to write any code to create and configure Appender, Layout, Pattern Converter, etc. Log4j automatically recognizes the plugins and uses them when the configuration references them. -Property support: You can reference properties in the configuration and Log4j replaces them directly, or Log4j passes them to the underlying component that dynamically resolves them.
--Java 8 Lambda support --Custom log level --Gardage-free: During steady-state logging, Log4j 2 is garbage-free for studded applications and low for web applications. This can reduce the pressure on the garbage collector and give better response time performance. --Integration with Application Server: Version 2.10.0 introduces the module log4j-appserver to improve the integration between Apache Tomcat and Eclipse Jetty.
Log4j 2 class diagram:
In this article, we'll explore the Log4j 2 source code from four aspects: launch, configuration, asynchronization, and plugin-based components.
Source code search
Startup
Main components of Log4j 2
-
LogManager LogManager initializes the corresponding LoggerContext based on the specified LogContextFactory.
-
LoggerContext
1. Parses the configuration file to obtain the corresponding Java object
2. Cache log configuration through LoggerRegisty
3. Obtain the configuration information
4. Use the start() method to parse the configuration file, and convert the configuration file into the corresponding Java object
5. Obtain the logger object through getLogger
- Logger LogManager LogManager is the key to start Log4j. Both LoggerContext and Logger are obtained by calling the static method of LogManager. To get the Logger, use the following code.
Logger logger = LogManager.getLogger();
You can see that LogManager is an important component. Therefore, here we will analyze the startup process of LogManager in detail.
Use the following static code snippet to launch LogManager.
/**
* 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();
}
}
}
This static snippet is implemented as follows:
- First, get the loggerContextFactory based on the configuration information in a particular config file.
- If you cannot find the implementation class for LoggerContextFactory, use the providerUtil's getProviders () method to load the provider. Next, load the implementation class of LoggerContextFactory with the loadLoggerContextFactory () method of the provider.
- If the provider fails to load the LoggerContextFactory implementation class or the provider is empty, use SimpleLoggerContextFactory as the LoggerContextFactory.
Load LoggerContextFactory according to the configuration file
// 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);
}
}
In this snippet, LogManager first gets the LoggerContextFactory using the "log4j2.loggerContextFactory" configuration item in the "log4j2.component.properties" configuration file. After completing the corresponding settings, instantiate the LoggerContextFactory object with the newCheckedInstanceOf () method. The following snippet shows how it works.
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();
}
}
By default, the initialization file log4j2.component.properties does not exist. Therefore, you need to get the LoggerContextFactory by some other method.
Use provider to instantiate LoggerContextFactory object
The code is:
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();
}
}
It's interesting that both hasProviders and getProviders use thread-safe methods to lazily initialize the ProviderUtil object. Let's take a look at the lazyInit () method.
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();
}
}
}
Let's see the construction method.
private ProviderUtil() {
for (final LoaderUtil.UrlResource resource : LoaderUtil.findUrlResources(PROVIDER_RESOURCE)) {
loadProvider(resource.getUrl(), resource.getClassLoader());
}
}
Initialization here means initializing the provider object. When you create a new instance of providerUtil, the provider object is instantiated directly. First, use the getClassLoaders () method to get the provider's classloaders. Then use loadProviders (classLoader); to load the class. The final step in instantiating providerUtil is a uniform search for the URL of the corresponding provider in the "META-INF / log4j-provider.properties" file. Consider loading the provider remotely. The loadProviders () method adds the provider to the ProviderUtil's PROVIDERS list. The default provider is org.apache.logging.log4j.core.impl.Log4jContextFactory.
LoggerContextFactory = org.apache.logging.log4j.core.impl.Log4jContextFactory
Log4jAPIVersion = 2.1.0
FactoryPriority= 10
Interestingly, lazy-init is locked using the lockInterruptibly () method. What is the difference between lockInterruptibly and lock? What is the difference between lock and lockInterruptibly?
lock first acquires the lock and then responds to the interrupt signal.
lockInterruptibly responds immediately to interrupt signals sent by other threads, rather than acquiring or reacquiring a lock.
ReentrantLock.lockInterruptibly has another thread
The Thread.interrupt () method of the thread waiting to acquire the lock stops the wait and returns immediately. In this case, the waiting thread does not acquire the lock. Instead, it throws an InterruptedException. ReentrantLock.lock does not allow thread interrupts when calling the Thread.interrupt () method. The thread will continue to retry the acquisition of the lock even if Thread.isInterrupted is detected. Threads that fail to acquire the lock are added to the wait queue. Finally, when a thread acquires a lock, it is put into an interrupted state and an interrupt occurs.
The comments above are noteworthy.
/**
* 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;
It turns out that this snippet is used to allow OSGi Activator to pause its launch.
Return to LogManager.
Once the provider is installed, LogManager will proceed with factory binding.
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());
}
The LogManager startup process ends here.
configuration
To get a logger without using slf4j
Logger logger = logManager.getLogger(xx.class)
Let's take a look at the getLogger () method.
public static Logger getLogger(final Class<? > clazz) {
final Class<? > cls = callerClass(clazz);
return getContext(cls.getClassLoader(), false).getLogger(toLoggerName(cls));
}
Let's take a look at the getContext () method.
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);
}
}
As mentioned earlier, the factory method is implemented in Log4jContextFactory. Let's take a look at getContext.
Method:
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;
}
Let's take a look at the start () method.
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);
}
The core method is reconfigure (). Move
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);
}
}
You can see that each setting comes from Configuration Factory. First, let's take a look at the getInstance () method of this class.
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;
}
You can see that ConfigurationFactory uses PluginManager for initialization. PluginManager loads a subclass of ConfigurationFactory. The default subclasses are XmlConfigurationFactory, JsonConfigurationFactory and YamlConfigurationFactory. These are loaded as plugins.
Return to the reconfigure () method. You can see that LogManager calls the getConfiguration () method after getting an instance of ConfigurationFactory.
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);
}
Let's take a look at the getConfiguration () method. Be careful not to get confused as getConfiguration () will be called multiple times. If you're not sure, try debugging.
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();
}
LogManager then gets the settings from the previously loaded configuration factory.
Return to the reconfigure () method. The next method to call is setConfiguration (), and specify the config obtained earlier as the input argument.
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;
}
The most important step of this method is config.start, which parses the configuration.
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);
}
The process involves the following steps:
- Get the log level plugin
- Initialization
- Advertiser initialization
- Configuration
In the initialization step, the setup () method is called. You need to override the setup () method. The operation is explained using XMLConfiguration as an example.
@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;
}
The important method constructHierarchy () is used here. Let's take a look at it.
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);
}
}
As you can see, it's a tree traversal process. Of course, the configuration file is provided in XML format. XML documents have a hierarchical structure and can be conceptually interpreted as a tree structure. Return to the start () method. Let's take a look at the doConfigure () method.
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();
}
You can see that this method parses the previously obtained configuration and inserts the result in the right place. Return to the start () method. Once configured, you need to launch the logger and appender.
Asynchronized
Asynchronous appender
AsyncAppender is a great feature that sets it apart from other log services. First, let's look at the mechanism from printing the log. Go to Logger and look for the logging method.
public void debug(final Marker marker, final Message msg) {
logIfEnabled(FQCN, Level.DEBUG, marker, msg, msg ! = null ? msg.getThrowable() : null);
}
I will move.
@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();
}
}
As you can see, the number of calls is recorded before printing the log. Let's take a look at the tryLogMessage () method.
@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);
}
}
I will move it.
@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);
}
As you can see, when printing a log, the log printing strategy is taken from config. Let's see how to create a ReliabilityStrategy. The default implementation class is DefaultReliabilityStrategy. Let's take a look at the actual log printing method.
@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);
}
The actual log printing method is implemented in config. It's pretty unusual. Please take a closer look.
@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);
}
}
You can see that the snippet before the try created the LogEvent and only the try part implements logging.
private void processLogEvent(final LogEvent event, LoggerConfigPredicate predicate) {
event.setIncludeLocation(isIncludeLocation());
if (predicate.allow(this)) {
callAppenders(event);
}
logParent(event, predicate);
}
Next, let's look at the callAppenders () method. First, from the append () method of AsyncAppender.
/**
* 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);
}
}
}
The important steps are:
- Create a LogEvent.
- Call the Transfer () method to add the LogEvent to the BlockingQueue.
- If the BlockingQueue is full, enable the corresponding strategy.
Similarly, threads are used to implement asynchronous consumption.
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
}
}
}
Let's see how the run () method works.
- Block the thread that gets the LogEvent.
- Send a LogEvent.
- The thread cannot be shut down until all the events in the blocking queue have been consumed.
Asynchronous logger
Let's start with AsyncLogger's logMessage () method.
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);
}
}
Let's take a look at the logWithThreadLocalTranslator () method.
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);
}
The logic of this method is straightforward. Converts log-related information to RingBufferLogEvent and publishes it to RingBuffer. The RingBuffer can be thought of as a Disruptor lock-free queue. It can be assumed that the log information will be processed by some consumption logic after being exposed to the RingBuffer. There are two ways to find this consumption logic:
--Find the location where Disruptor is used and check the details. However, doing so can easily get confused. --Log4j 2 loggers usually have their own start () method. Try it with that start () method.
There is a snippet inside the start () method.
final RingBufferLogEventHandler[] handlers = {new RingBufferLogEventHandler()};
disruptor.handleEventsWith(handlers);
Let's see how the RingBufferLogEventHandler class is implemented.
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() {
}
}
Then you will have the following interface.
/**
* 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;
}
From the comments, you can see that the onEvent () method is the processing logic. Returning to the onEvent () method of RingBufferLogEventHandler, there is an execute () method as shown below.
public void execute(final boolean endOfBatch) {
this.endOfBatch = endOfBatch;
asyncLogger.actualAsyncLog(this);
}
Use this method to output the log. AsyncLogger seems simple, it just uses Disruptor.
Plugin-based components
In other code snippets, you'll often see something like this:
final PluginManager manager = new PluginManager(CATEGORY);
manager.collectPlugins(pluginPackages);
Many Log4j 2 components are made up of plugins for better extensibility. You need to load plugin-based components during configuration.
Take a look at 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;
}
The processing logic is as follows.
- Load all built-in plugins from the Log4j2Plugin.dat file.
- Load all plugins from the OSGi Bundles Log4j2Plugin.dat file.
- Load the plugin passed to the package path.
- Finally, load the plugin from the settings.
Logic is not straightforward. However, when I checked the source code, I found it interesting. When I load the Log4j 2 core plugin, it looks like this:
PluginRegistry.getInstance().loadFromMainClassLoader()
Let's take a look at the decodeCacheFiles () method.
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;
}
You can see that all the required plugins are loaded from the same file. PLUGIN_CACHE_FILE. I was wondering why the plugin loads from a file instead of scanning it directly with reflect? If you write the plugin to a file, it will not be extensible. So I searched for how to use the static variable PLUGIN_CACHE_FILE. Then I found a PluginProcessor class that uses an annotation processor.
/**
* 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;
}
}
}
(The less important method is omitted)
In the process () method, you can see that the PluginProcessor class first collects all the plugins and writes them to a file. Doing so saves reflection overhead.
Take a look at the comments about the plugin. The plugin's Retention Policy is RUNTIME. Generally, Plugin Processor uses RetentionPolicy.SOURCE and CLASS together. If you're scanning the plugin and writing to a file, it doesn't make sense to set the Retention Policy to RUNTIME. This is something I'm not sure about.
Summary
Finally, we passed the Log4j 2 code. I was impressed with the design concept of improving flexibility by plugging components. With the rapid development of Internet technology, various middlewares have appeared. We need to think more about the relationship between one code and another. There is no doubt that the decoupled relationship is the most beautiful.
- Alibaba Cloud is the No. 1 (2019 Gartner) cloud infrastructure operator in the Asia Pacific region with two data centers in Japan and more than 60 availability zones in the world. Click here for more information on Alibaba Cloud. Alibaba Cloud Japan Official Page *
Recommended Posts