Exception thrown in class annotated with @Plugin that uses a logger

[bfreitastgtg]

Description

Trying to use a logger in a class annotated with @Plugin from org.apache.logging.log4j.core.config.plugins throws an exception. The same problem does not happen on versions 2.23.1, 2.24.0 and 2.24.1.

Configuration

Version: 2.24.2

Operating system: linux

JDK: Amazon Correto, 21

Logs

2024-11-26T08:33:59.000998374Z main ERROR Unable to create Lookup for myplugin java.lang.IllegalArgumentException: java.lang.ExceptionInInitializerError
	at org.apache.logging.log4j.core.util.ReflectionUtil.instantiate(ReflectionUtil.java:192)
	at org.apache.logging.log4j.core.lookup.Interpolator.<init>(Interpolator.java:90)
	at org.apache.logging.log4j.core.lookup.Interpolator.<init>(Interpolator.java:109)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.<init>(AbstractConfiguration.java:137)
	at org.apache.logging.log4j.core.config.NullConfiguration.<init>(NullConfiguration.java:32)
	at org.apache.logging.log4j.core.LoggerContext.<clinit>(LoggerContext.java:77)
	at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.createContext(ClassLoaderContextSelector.java:265)
	at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.locateContext(ClassLoaderContextSelector.java:224)
	at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:142)
	at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:125)
	at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:119)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:148)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:46)
	at org.apache.logging.log4j.LogManager.getContext(LogManager.java:138)
	at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:136)
	at org.apache.logging.slf4j.Log4jLoggerFactory.getContext(Log4jLoggerFactory.java:58)
	at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:46)
	at org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:32)
	at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:432)
	at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:457)
        (...)
Caused by: java.lang.ExceptionInInitializerError
	at java.base/jdk.internal.misc.Unsafe.ensureClassInitialized0(Native Method)
	at java.base/jdk.internal.misc.Unsafe.ensureClassInitialized(Unsafe.java:1160)
	at java.base/jdk.internal.reflect.MethodHandleAccessorFactory.ensureClassInitialized(MethodHandleAccessorFactory.java:300)
	at java.base/jdk.internal.reflect.MethodHandleAccessorFactory.newConstructorAccessor(MethodHandleAccessorFactory.java:103)
	at java.base/jdk.internal.reflect.ReflectionFactory.newConstructorAccessor(ReflectionFactory.java:200)
	at java.base/java.lang.reflect.Constructor.acquireConstructorAccessor(Constructor.java:549)
	at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499)
	at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:486)
	at org.apache.logging.log4j.core.util.ReflectionUtil.instantiate(ReflectionUtil.java:188)
	... 20 more
Caused by: java.lang.NullPointerException: messageFactory
	at java.base/java.util.Objects.requireNonNull(Objects.java:259)
	at org.apache.logging.log4j.core.util.internal.InternalLoggerRegistry.computeIfAbsent(InternalLoggerRegistry.java:135)
	at org.apache.logging.log4j.core.LoggerContext.getLogger(LoggerContext.java:530)
	at org.apache.logging.log4j.core.LoggerContext.getLogger(LoggerContext.java:503)
	at org.apache.logging.log4j.core.LoggerContext.getLogger(LoggerContext.java:65)
	at org.apache.logging.slf4j.Log4jLoggerFactory.newLogger(Log4jLoggerFactory.java:49)
	at org.apache.logging.slf4j.Log4jLoggerFactory.newLogger(Log4jLoggerFactory.java:32)
	at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:52)
	at org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:32)
	at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:432)
	at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:457)
	(...)
	... 29 more

Reproduction

The code below used to run fine, then after upgrading to 2.24.2 it started throwing on application startup. Getting rid of the LOGGER variable "fixes" the problem.

import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.config.plugins.Plugin;
import org.apache.logging.log4j.core.lookup.StrLookup;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

@Plugin(name = "MyPlugin", category = StrLookup.CATEGORY)
public class MyPlugin implements StrLookup {
  private static final Logger LOGGER = LoggerFactory.getLogger(MyPlugin.class);

  static {
    LOGGER.info("Log stuff");
  }

  @Override
  public String lookup(String key) {
    return "";
  }

  @Override
  public String lookup(LogEvent event, String key) {
    return "";
  }
}

[ppkarwasz]

@bfreitastgtg,

Thanks for reporting it. Log4j loads all annotated implementations of StrLookup in the static initialization of LoggerContext. When you class requests the logger, LoggerContext is not completely initialized. You will get all sorts of NPEs in this case.

There is a special logger (see Status Logger) that you can use in Log4j Plugins, but you should not use loggers obtained from LogManager or some foreign logging API bridged to Log4j API.

[bfreitastgtg]

Hey @ppkarwasz , thanks for the quick reply. I tested and using a StatusLogger worked, but the question remains: why we suddenly needed to use it? As mentioned in the description, using a regular logger worked fine before 2.24.2.

[ppkarwasz]

Hey @ppkarwasz , thanks for the quick reply. I tested and using a StatusLogger worked, but the question remains: why we suddenly needed to use it? As mentioned in the description, using a regular logger worked fine before 2.24.2.

The problem you are encountering is due to the DEFAULT_MESSAGE_FACTORY field being uninitialized (so null).
Up to Log4j 2.22.x, that field was in the Log4j API (its classes are initialized before LoggerContext) and was initialized using reflection and a configuration property specific to Log4j 2 (the log4j2.messageFactory property). That solution is no longer viable:

• It is not extensible. Since the release of 2.24.0, Log4j Core 3 is based on the same version of Log4j API as Log4j Core 2 (see documentation), but uses dependency injection for many services (including MessageFactory).
• It causes problems for GraalVM, since we would need to register with GraalVM all possible MessageFactory implementations in advance.
• It causes other initialization problems: since 2.23.x StatusLogger uses AbstractLogger, but is initialized before PropertiesUtil, which is used to determine the right MessageFactory.

These are the main reasons we moved the initialization of the default message factory at a later stage.

Note: we can easily fix the initialization problem, by moving DEFAULT_MESSAGE_FACTORY at the top of the LoggerContext class, but I have mixed feeling about this approach:

• I don't think it is needed. Using any o.a.l.l.Logger other than o.a.l.l.status.StatusLogger in a Log4j Core Plugin class is IMHO bad practice. Using an org.slf4j.Logger in such a class is even less recommended.
• The real problem is elsewhere: the DefaultConfiguration and NullConfiguration implementations used by LoggerContext before and after the real configuration is loaded, should probably be pretty minimal and should not require lookups and other advanced services, since they are basically immutable. We should probably go in this direction, but this might require breaking changes, which are not allowed in 2.x.