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 classes diagram:
This article explores the source code of Log4j 2 in four aspects: startup, configuration, asynchronization, and plug-in-based components.
Main components of Log4j 2
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
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:
Logger logger = LogManager.getLogger();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:
/**
* 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 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.
// 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 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:
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 initial configuration file log4j2.component.properties does not exist. Therefore, you need to obtain the LoggerContextFactory through other ways.
Code:
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 is interesting that both hasProviders and getProviders lazily initialize the ProviderUtil object through a thread-safe method. 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();
}
}
}Take a look at the construction method:
private ProviderUtil() {
for (final LoaderUtil.UrlResource resource : LoaderUtil.findUrlResources(PROVIDER_RESOURCE)) {
loadProvider(resource.getUrl(), resource.getClassLoader());
}
}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.
LoggerContextFactory = org.apache.logging.log4j.core.impl.Log4jContextFactory
Log4jAPIVersion = 2.1.0
FactoryPriority= 10Interesting 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:
/**
* 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 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.
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 startup process of the LogManager ends here.
Without using slf4j, you can use the following method to get the logger:
Logger logger = logManager.getLogger(xx.class)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));
}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 previously, the factory methods are implemented by Log4jContextFactory. Take a look at the 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;
}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 on.
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 configuration comes from the ConfigurationFactory. Take a look at the getInstance() method of this class first:
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 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:
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);
}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.
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();
}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.
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);
}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:
@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;
}An important method constructHierarchy() is used here. 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, 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:
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 to the right place. Return to the start() method. After completing the configuration, you need to start the logger and appender.
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.
public void debug(final Marker marker, final Message msg) {
logIfEnabled(FQCN, Level.DEBUG, marker, msg, msg ! = null ? msg.getThrowable() : null);
}Keep moving.
@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 calls is recorded before log printing. 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);
}
}Keep moving.
@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, 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:
@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 by a config. It is a quite unusual. 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 clearly see that the snippet before try creates the LogEvent, and only the try part implements logging. Keep moving.
private void processLogEvent(final LogEvent event, LoggerConfigPredicate predicate) {
event.setIncludeLocation(isIncludeLocation());
if (predicate.allow(this)) {
callAppenders(event);
}
logParent(event, predicate);
}Next, we will take a look at the callAppenders() method. First, start with 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 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.
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
}
}
}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.
Let us start with the logMessage() method of the AsyncLogger:
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);
}
}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 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:
In the start() method, you can find a snippet:
final RingBufferLogEventHandler[] handlers = {new RingBufferLogEventHandler()};
disruptor.handleEventsWith(handlers);Take a look at 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 can find 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, 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:
public void execute(final boolean endOfBatch) {
this.endOfBatch = endOfBatch;
asyncLogger.actualAsyncLog(this);
}This method is used to print logs. AsyncLogger looks to be simple, and it only uses a Disruptor.
The following is frequently seen in many other code snippets:
final PluginManager manager = new PluginManager(CATEGORY);
manager.collectPlugins(pluginPackages);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.
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 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:
PluginRegistry.getInstance().loadFromMainClassLoader()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 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.
/**
* 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;
}
}
}(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.
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.
Detailed Explanation of Guava RateLimiter's Throttling Mechanism
2,599 posts | 762 followers
FollowAlibaba Clouder - November 8, 2019
Alibaba Cloud Community - November 9, 2021
Alibaba Cloud Community - June 14, 2024
Alibaba Cloud Storage - June 19, 2019
Alibaba Clouder - November 11, 2019
Alibaba Cloud Community - January 25, 2024
2,599 posts | 762 followers
Follow
Simple Log Service
An all-in-one service for log-type data
Learn More
ECS(Elastic Compute Service)
Elastic and secure virtual cloud servers to cater all your cloud hosting needs.
Learn More
API Gateway
API Gateway provides you with high-performance and high-availability API hosting services to deploy and release your APIs on Alibaba Cloud products.
Learn MoreMore Posts by Alibaba Clouder