Exploring the Secrets of Java Logs: Log4j 2 Log System

Overview

Log4j 2 is a completely new log system built on Apache Log4j by referencing the logback architecture. I believe that is because Log4J has essentially been deprecated by Logback.

For advantages of Log4j 2, see the official document Apache Log4j 2:

  • Log4j 2 provides many of the improvements available in Logback while fixing some inherent problems in the Logback architecture.123
  • API separation: The Log4j 2 API is a logging facade that may be used with the Log4j 2 implementation, but may also be used in front of other logging implementations such as Logback (Although I don’t think anyone would do this.)
  • Improved performance: Log4j 2 contains next-generation Asynchronous Loggers based on the LMAX Disruptor library. In multi-threaded scenarios Asynchronous Loggers have 18 times higher throughput and orders of magnitude lower latency than Log4j and Logback.
  • Support for multiple APIs: Log4j 2 provides support for the Log4j 1.2, SLF4J, Commons Logging and java.util.logging (JUL) APIs.
  • Avoid lock-in: Applications coded to the Log4j 2 API always have the option to use any SLF4J-compliant library as their logger implementation with the log4j-to-slf4j adapter.
  • Automatic reloading of configurations: Like Logback, Log4j 2 can automatically reload its configuration upon modification. Unlike Logback, it will do so without losing log events while reconfiguration is taking place.
  • Advanced filtering: Like Logback, Log4j 2 supports filtering based on context data, markers, regular expressions, and other components in the Log event.
  • Plugin architecture: Log4j uses the plug-in pattern to configure components. As such, you do not need to write code to create and configure an Appender, Layout, Pattern Converter, and so on. Log4j automatically recognizes plug-ins and uses them when a configuration references them.
  • Property support: You can reference properties in a configuration, Log4j will directly replace them, or Log4j will pass them to an underlying component that will dynamically resolve them.
  • Java 8 Lambda support
  • Custom log levels
  • Garbage-free: During steady state logging, Log4j 2 is garbage-free in stand-alone applications, and low garbage in web applications. This reduces pressure on the garbage collector and can give better response time performance.
  • Integrating with application servers: Version 2.10.0 introduces a the module log4j-appserver to improve integration with Apache Tomcat and Eclipse Jetty.

Log4j 2 classes diagram:

This article explores the source code of Log4j 2 in four aspects: startup, configuration, asynchronization, and plug-in-based components.

Source Code Exploration

Startup

Main components of Log4j 2

  • LogManager

The 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

The LogManager is the key to start Log4j. Both the LoggerContext and Logger are obtained by calling the static method of LogManager. You can use the following code to obtain the Logger:

You can see that the LogManager is a critical component. Therefore, this section will analyze the startup process of the LogManager in detail.

You can use the following static code snippet to start the LogManager:

This static snippet is implemented in the following steps:

1. First, obtain the loggerContextFactory based on the configuration information of the specific configuration file.
2. If the implementation class of the LoggerContextFactory is not found, load providers by using the getProviders() method of ProviderUtil. Then load the implementation class of the LoggerContextFactory by using the loadLoggerContextFactory() method of the provider.
3. If the implementation class of the LoggerContextFactory fails to be loaded from the provider or the provider is empty, use SimpleLoggerContextFactory as the LoggerContextFactory.

Load the LoggerContextFactory according to the configuration file

In this snippet, LogManager first uses the “log4j2.loggerContextFactory” configuration item of the “log4j2.component.properties” configuration file to obtain the LoggerContextFactory. If you have completed the corresponding configuration, you can use the newCheckedInstanceOf() method to instantiate the object of LoggerContextFactory. The following snippet shows how it works:

By default, the initial configuration file log4j2.component.properties does not exist. Therefore, you need to obtain the LoggerContextFactory through other ways.

Use Provider to instantiate the LoggerContextFactory object

Code:

It is interesting that both hasProviders and getProviders lazily initialize the ProviderUtil object through a thread-safe method. Take a look at the lazyInit() method:

Take a look at the construction method:

Lazy initialization here is to lazily initialize the provider object. When you create a new providerUtil instance, the provider object is instantiated directly. First, obtain the class loader of the provider by using the getClassLoaders() method. Then use loadProviders(classLoader); to load the class. The last step of providerUtil instantiation uniformly searches for the URL of the corresponding provider in the “META-INF/log4j-provider.properties” file. Remotely loading the provider will be considered. The loadProviders() method adds a provider to the PROVIDERS list of ProviderUtil. The default provider is org.apache.logging.log4j.core.impl.Log4jContextFactory.

Interesting enough, lazy-init is locked by using the lockInterruptibly() method. Differences between lockInterruptibly and lock are:

Differences between lock and lockInterruptibly are:

lock first acquires the lock, and reacts to the interrupt signal only after acquiring the lock.

lockInterruptibly immediately reacts to the interrupt signal sent to it from another thread, instead of acquiring the lock or reacquiring the lock.

ReentrantLock.lockInterruptibly allows another thread to call the

Thread.interrupt() method of a thread that is waiting to acquire the lock to stop waiting and return immediately. In this case, the waiting thread does not acquire the lock. Instead, it throws an InterruptedException. The ReentrantLock.lock does not allow the thread to be interrupted by calling the Thread.interrupt() method. The thread continues to retry acquiring the lock even when Thread.isInterrupted is detected. The thread is added to waiting queue after failing to acquire the lock. At last, when the thread acquires the lock, the thread is set to the interrupted state, and then it is interrupted.

A comment above is worth noting:

It turns out that the snippet is used to allow the OSGi Activator to pause the startup.

Return to the LogManager.

After the provider is installed, the LogManager proceeds with factory binding.

The startup process of the LogManager ends here.

Configuration

Without using slf4j, you can use the following method to get the logger:

Take a look at the getLogger() method:

Take a look at the getContext() method:

As mentioned previously, the factory methods are implemented by Log4jContextFactory. Take a look at the getContext

method:

Take a look at the start() method:

The core method is reconfigure(). Move on.

You can see that each configuration comes from the ConfigurationFactory. Take a look at the getInstance() method of this class first:

You can see that the ConfigurationFactory uses the PluginManager for initialization. The PluginManager loads subclasses of the ConfigurationFactory. The default subclasses are XmlConfigurationFactory, JsonConfigurationFactory, and YamlConfigurationFactory. They are loaded as plug-ins.

Return to the reconfigure() method. You can see that, LogManager calls the getConfiguration() method after obtaining the ConfigurationFactory instance:

Take a look at the getConfiguration() method. Note that getConfiguration() is called multiple times, do not get confused. If you are not clear, try debugging.

Then, LogManager obtains the configuration from the configuration factory that has been loaded previously.

Return to the reconfigure() method. The next method to be called is setConfiguration(), and the input argument is config that we obtained in the previous step.

The most important step of this method is config.start, which parses the configuration.

This process involves the following steps:

1. Obtain log-level plug-ins
2. Initialization
3. Initialize Advertiser
4. Configuration

During the initialization step, the setup() method is called. The setup() method needs to be overwritten. We will show you how it works by using XMLConfiguration as an example:

An important method constructHierarchy() is used here. Take a look at it:

As you can see, this is a tree traversal process. Of course, the configuration file is provided in XML format. XML documents have a hierarchical structure and can conceptually be interpreted as a tree structure. Return to the start() method. Take a look at the doConfigure() method:

You can see that, this method parses the previously obtained configuration, and inserts the result to the right place. Return to the start() method. After completing the configuration, you need to start the logger and appender.

Asynchronization

AsyncAppender

AsyncAppender is an outstanding feature that differentiates Log4j 2 from other logging services. We will start with log printing to see how it works. Go to the Logger, and find a logging method.

Keep moving.

As you can see, the number calls is recorded before log printing. Take a look at the tryLogMessage() method:

Keep moving.

As you can see, upon log printing, the log printing strategy is retrieved from config. Take a look at how the ReliabilityStrategy is created. The default implementation class is DefaultReliabilityStrategy. Take a look at the actual log printing method:

The actual log printing method is implemented by a config. It is a quite unusual. Take a closer look:

You can clearly see that the snippet before try creates the LogEvent, and only the try part implements logging. Keep moving.

Next, we will take a look at the callAppenders() method. First, start with the append() method of AsyncAppender:

The key steps are:

1. Create the LogEvent
2. Add the LogEvent to the BlockingQueue by calling the transfer() method
3. If the BlockingQueue is full, enable the corresponding strategy

Likewise, a thread is used to implement asynchronous consumption.

Take a look at how the run() method works:

1. Block the thread to obtain the LogEvent
2. Send out the LogEvent
3. A thread cannot be shut down until all events of the blocking queue are consumed.

AsyncLogger

Let us start with the logMessage() method of the AsyncLogger:

Take a look at the logWithThreadLocalTranslator() method:

The logic of this method is straight forward. It converts the log-related information into the RingBufferLogEvent, and then publishes it to the RingBuffer. RingBuffer can be considered a lock-free queue of Disruptor. We can assume that the log information will be processed by some consumption logic after being published to the RingBuffer. We can find this consumption logic using one of two ways:

  • Locate where the disruptor is used, and then check the details. However, you may easily get confused when doing so.
  • Loggers of Log4j 2 usually have their own start() method. We can try with the start() method.

In the start() method, you can find a snippet:

Take a look at how the RingBufferLogEventHandler class is implemented:

Then you can find the following interface:

From the comments, we can find that the onEvent() method is the processing logic. Return to the onEvent() method of RingBufferLogEventHandler, we can find an execute() method as follows:

This method is used to print logs. AsyncLogger looks to be simple, and it only uses a Disruptor.

Plug-in-based Components

The following is frequently seen in many other code snippets:

To achieve better extensibility, many Log4j 2 components are made in plug-ins. You need to load plug-in-based components during configuration.

Take a look at collectPlugins.

The processing logic is listed as follows:

1. Load all built-in plug-ins from Log4j2Plugin.dat files
2. Load all plug-ins from Log4j2Plugin.dat files of OSGi Bundles
3. Load plug-ins that have been passed to the package path
4. At last, load plug-ins from the configuration

The logic is straight forward. However, when I check the source code, I found something interesting. When we load Log4j 2 core plug-ins, the following method is used:

Take a look at the decodeCacheFiles() method:

You can see that all required plug-ins are loaded from the same file: PLUGIN_CACHE_FILE. I was wondering why it loads plug-ins from files instead of directly scanning them through reflection? When plug-ins are written into files, they are not easily scalable. Then I searched for the use of the static variable PLUGIN_CACHE_FILE. I found the PluginProcessor class, which uses an annotation processor.

(Less important methods are omitted)

You can see that in the process() method, the PluginProcessor class first collects all plug-ins, and then writes them into files. By doing so, it saves the reflection overhead.

Take a look at the comment for plug-ins. The RetentionPolicy of plug-ins is RUNTIME. Generally, PluginProcessor is used in conjunction with RetentionPolicy.SOURCE and CLASS. If we have already scanned the plug-ins and written them into files, it makes no sense to set RetentionPolicy to RUNTIME. This is something that I do not quite understand.

Summary

At last, we have gone through the code of Log4j 2. Its design ideas are inspiring — developing components into plug-ins improves the flexibility. With the rapid development of Internet technologies, various middleware products have been springing up. We need to think more about the relationship between one code and another. Undoubtedly, the decoupled relationship is the most beautiful one.

Reference:https://www.alibabacloud.com/blog/exploring-the-secrets-of-java-logs-log4j-2-log-system_594821?spm=a2c41.12911994.0.0

Follow me to keep abreast with the latest technology news, industry insights, and developer trends.

Get the Medium app

A button that says 'Download on the App Store', and if clicked it will lead you to the iOS App store
A button that says 'Get it on, Google Play', and if clicked it will lead you to the Google Play store