From cb59a70fb55be6a9c5ef74d1f0dc207a8fdfedd0 Mon Sep 17 00:00:00 2001 From: "Piotr P. Karwasz" Date: Mon, 2 Dec 2024 15:53:41 +0100 Subject: [PATCH] Hardens `PropertiesUtil` against recursive property sources As showed in #3252, Spring's `JndiPropertySource` not only can throw exceptions, but can also perform logging calls. Such a call causes a recursive call to `PropertiesUtil.getProperty("log4j2.flowMessageFactory"`) and a `StackOverflowException` in the best scenario. The worst scenario includes a deadlock. This PR: - Moves the creation of the default `MessageFactory` and `FlowMessageFactory` to the static initializer of `LoggerContext`. This should be close enough to the pre-2.23.0 location in `AbstractLogger`. The `LoggerContext` class is usually initialized, before Spring Boot adds its property sources to `PropertiesUtil`. - Adds a check to `PropertiesUtil` to ignore recursive calls. Closes #3252. --- .../log4j/util/PropertiesUtilTest.java | 48 +++++++++++- .../logging/log4j/util/PropertiesUtil.java | 35 ++++++--- ...LoggerMessageFactoryCustomizationTest.java | 38 +++++----- ...rMessageFactoryDefaultsTlaEnabledTest.java | 15 ++-- .../impl/ThreadContextDataInjectorTest.java | 2 - .../org/apache/logging/log4j/core/Logger.java | 75 +++---------------- .../logging/log4j/core/LoggerContext.java | 62 ++++++++++++--- .../logging/log4j/core/async/AsyncLogger.java | 18 ++--- 8 files changed, 173 insertions(+), 120 deletions(-) diff --git a/log4j-api-test/src/test/java/org/apache/logging/log4j/util/PropertiesUtilTest.java b/log4j-api-test/src/test/java/org/apache/logging/log4j/util/PropertiesUtilTest.java index a655959765c..0203eff1225 100644 --- a/log4j-api-test/src/test/java/org/apache/logging/log4j/util/PropertiesUtilTest.java +++ b/log4j-api-test/src/test/java/org/apache/logging/log4j/util/PropertiesUtilTest.java @@ -193,7 +193,7 @@ void testPublish() { @Test @ResourceLock(value = Resources.SYSTEM_PROPERTIES, mode = ResourceAccessMode.READ) @Issue("https://github.com/spring-projects/spring-boot/issues/33450") - void testBadPropertySource() { + void testErrorPropertySource() { final String key = "testKey"; final Properties props = new Properties(); props.put(key, "test"); @@ -208,6 +208,28 @@ void testBadPropertySource() { } } + @Test + @ResourceLock(value = Resources.SYSTEM_PROPERTIES, mode = ResourceAccessMode.READ) + @Issue("https://github.com/apache/logging-log4j2/issues/3252") + void testRecursivePropertySource() { + final String key = "testKey"; + final Properties props = new Properties(); + props.put(key, "test"); + final PropertiesUtil util = new PropertiesUtil(props); + final PropertySource source = new RecursivePropertySource(util); + util.addPropertySource(source); + try { + // We ignore the recursive source + assertThat(util.getStringProperty(key)).isEqualTo("test"); + assertThat(util.hasProperty(key)).isTrue(); + // We check that the source is recursive + assertThat(source.getProperty(key)).isEqualTo("test"); + assertThat(source.containsProperty(key)).isTrue(); + } finally { + util.removePropertySource(source); + } + } + private static final String[][] data = { {null, "org.apache.logging.log4j.level"}, {null, "Log4jAnotherProperty"}, @@ -289,4 +311,28 @@ public boolean containsProperty(final String key) { throw new IllegalStateException("Test"); } } + + private static class RecursivePropertySource implements PropertySource { + + private final PropertiesUtil propertiesUtil; + + private RecursivePropertySource(PropertiesUtil propertiesUtil) { + this.propertiesUtil = propertiesUtil; + } + + @Override + public int getPriority() { + return Integer.MIN_VALUE; + } + + @Override + public String getProperty(String key) { + return propertiesUtil.getStringProperty(key); + } + + @Override + public boolean containsProperty(String key) { + return propertiesUtil.hasProperty(key); + } + } } diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/util/PropertiesUtil.java b/log4j-api/src/main/java/org/apache/logging/log4j/util/PropertiesUtil.java index 8b4baf4e531..30b92854b0c 100644 --- a/log4j-api/src/main/java/org/apache/logging/log4j/util/PropertiesUtil.java +++ b/log4j-api/src/main/java/org/apache/logging/log4j/util/PropertiesUtil.java @@ -496,6 +496,7 @@ public void reload() {} private static final class Environment { private final Set sources = ConcurrentHashMap.newKeySet(); + private final ThreadLocal CURRENT_PROPERTY_SOURCE = new ThreadLocal<>(); private Environment(final PropertySource propertySource) { final PropertySource sysProps = new PropertyFilePropertySource(LOG4J_SYSTEM_PROPERTIES_FILE_NAME, false); @@ -547,21 +548,35 @@ private String get(final String key) { } private boolean sourceContainsProperty(final PropertySource source, final String key) { - try { - return source.containsProperty(key); - } catch (final Exception e) { - LOGGER.warn("Failed to retrieve Log4j property {} from property source {}.", key, source, e); - return false; + PropertySource recursiveSource = CURRENT_PROPERTY_SOURCE.get(); + if (recursiveSource == null) { + CURRENT_PROPERTY_SOURCE.set(source); + try { + return source.containsProperty(key); + } catch (final Exception e) { + LOGGER.warn("Failed to retrieve Log4j property {} from property source {}.", key, source, e); + } finally { + CURRENT_PROPERTY_SOURCE.remove(); + } } + LOGGER.warn("Recursive call to `containsProperty()` from property source {}.", recursiveSource); + return false; } private String sourceGetProperty(final PropertySource source, final String key) { - try { - return source.getProperty(key); - } catch (final Exception e) { - LOGGER.warn("Failed to retrieve Log4j property {} from property source {}.", key, source, e); - return null; + PropertySource recursiveSource = CURRENT_PROPERTY_SOURCE.get(); + if (recursiveSource == null) { + CURRENT_PROPERTY_SOURCE.set(source); + try { + return source.getProperty(key); + } catch (final Exception e) { + LOGGER.warn("Failed to retrieve Log4j property {} from property source {}.", key, source, e); + } finally { + CURRENT_PROPERTY_SOURCE.remove(); + } } + LOGGER.warn("Recursive call to `getProperty()` from property source {}.", recursiveSource); + return null; } private boolean containsKey(final String key) { diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/LoggerMessageFactoryCustomizationTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/LoggerMessageFactoryCustomizationTest.java index 9043c47b1c7..1ac5c7cdf8e 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/LoggerMessageFactoryCustomizationTest.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/LoggerMessageFactoryCustomizationTest.java @@ -24,34 +24,36 @@ import org.apache.logging.log4j.message.MessageFactory; import org.apache.logging.log4j.message.ParameterizedMessageFactory; import org.junit.jupiter.api.Test; -import org.junitpioneer.jupiter.ClearSystemProperty; import org.junitpioneer.jupiter.SetSystemProperty; +@SetSystemProperty( + key = "log4j2.messageFactory", + value = "org.apache.logging.log4j.core.LoggerMessageFactoryCustomizationTest$TestMessageFactory") +@SetSystemProperty( + key = "log4j2.flowMessageFactory", + value = "org.apache.logging.log4j.core.LoggerMessageFactoryCustomizationTest$TestFlowMessageFactory") class LoggerMessageFactoryCustomizationTest { @Test - @ClearSystemProperty(key = "log4j2.messageFactory") - @ClearSystemProperty(key = "log4j2.flowMessageFactory") void arguments_should_be_honored() { - final LoggerContext loggerContext = - new LoggerContext(LoggerMessageFactoryCustomizationTest.class.getSimpleName()); - final Logger logger = new Logger( - loggerContext, "arguments_should_be_honored", new TestMessageFactory(), new TestFlowMessageFactory()); - assertTestMessageFactories(logger); + try (LoggerContext loggerContext = + new LoggerContext(LoggerMessageFactoryCustomizationTest.class.getSimpleName())) { + Logger logger = new Logger( + loggerContext, + "arguments_should_be_honored", + new TestMessageFactory(), + new TestFlowMessageFactory()); + assertTestMessageFactories(logger); + } } @Test - @SetSystemProperty( - key = "log4j2.messageFactory", - value = "org.apache.logging.log4j.core.LoggerMessageFactoryCustomizationTest$TestMessageFactory") - @SetSystemProperty( - key = "log4j2.flowMessageFactory", - value = "org.apache.logging.log4j.core.LoggerMessageFactoryCustomizationTest$TestFlowMessageFactory") void properties_should_be_honored() { - final LoggerContext loggerContext = - new LoggerContext(LoggerMessageFactoryCustomizationTest.class.getSimpleName()); - final Logger logger = new Logger(loggerContext, "properties_should_be_honored", null, null); - assertTestMessageFactories(logger); + try (LoggerContext loggerContext = + new LoggerContext(LoggerMessageFactoryCustomizationTest.class.getSimpleName())) { + Logger logger = loggerContext.getLogger("properties_should_be_honored"); + assertTestMessageFactories(logger); + } } private static void assertTestMessageFactories(Logger logger) { diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/LoggerMessageFactoryDefaultsTlaEnabledTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/LoggerMessageFactoryDefaultsTlaEnabledTest.java index 3255566710c..4a83ef90e96 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/LoggerMessageFactoryDefaultsTlaEnabledTest.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/LoggerMessageFactoryDefaultsTlaEnabledTest.java @@ -28,14 +28,15 @@ class LoggerMessageFactoryDefaultsTlaEnabledTest { @Test - @SetSystemProperty(key = "log4j2.is.webapp", value = "false") - @SetSystemProperty(key = "log4j2.enableThreadLocals", value = "true") + @SetSystemProperty(key = "log4j2.isWebapp", value = "false") + @SetSystemProperty(key = "log4j2.enableThreadlocals", value = "true") void defaults_should_match_when_thread_locals_enabled() { assertThat(Constants.ENABLE_THREADLOCALS).isTrue(); - final LoggerContext loggerContext = - new LoggerContext(LoggerMessageFactoryDefaultsTlaEnabledTest.class.getSimpleName()); - final Logger logger = new Logger(loggerContext, "defaults_should_match_when_thread_locals_enabled", null, null); - assertThat((MessageFactory) logger.getMessageFactory()).isSameAs(ReusableMessageFactory.INSTANCE); - assertThat(logger.getFlowMessageFactory()).isSameAs(DefaultFlowMessageFactory.INSTANCE); + try (LoggerContext loggerContext = + new LoggerContext(LoggerMessageFactoryDefaultsTlaEnabledTest.class.getSimpleName())) { + Logger logger = loggerContext.getLogger("defaults_should_match_when_thread_locals_enabled"); + assertThat((MessageFactory) logger.getMessageFactory()).isSameAs(ReusableMessageFactory.INSTANCE); + assertThat(logger.getFlowMessageFactory()).isSameAs(DefaultFlowMessageFactory.INSTANCE); + } } } diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/impl/ThreadContextDataInjectorTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/impl/ThreadContextDataInjectorTest.java index 896d0d2d8b7..135ea4162a0 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/impl/ThreadContextDataInjectorTest.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/impl/ThreadContextDataInjectorTest.java @@ -33,7 +33,6 @@ import org.apache.logging.log4j.ThreadContext; import org.apache.logging.log4j.core.ContextDataInjector; import org.apache.logging.log4j.spi.ThreadContextMap; -import org.apache.logging.log4j.util.PropertiesUtil; import org.apache.logging.log4j.util.ProviderUtil; import org.apache.logging.log4j.util.SortedArrayStringMap; import org.apache.logging.log4j.util.StringMap; @@ -59,7 +58,6 @@ public static Collection threadContextMapClassNames() { public String threadContextMapClassName; private static void resetThreadContextMap() { - PropertiesUtil.getProperties().reload(); final Log4jProvider provider = (Log4jProvider) ProviderUtil.getProvider(); provider.resetThreadContextMap(); ThreadContext.init(); diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/Logger.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/Logger.java index 169c39162db..fdd2465099f 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/Logger.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/Logger.java @@ -33,16 +33,11 @@ import org.apache.logging.log4j.core.config.LoggerConfig; import org.apache.logging.log4j.core.config.ReliabilityStrategy; import org.apache.logging.log4j.core.filter.CompositeFilter; -import org.apache.logging.log4j.core.util.Constants; -import org.apache.logging.log4j.message.DefaultFlowMessageFactory; import org.apache.logging.log4j.message.FlowMessageFactory; import org.apache.logging.log4j.message.Message; import org.apache.logging.log4j.message.MessageFactory; -import org.apache.logging.log4j.message.ParameterizedMessageFactory; -import org.apache.logging.log4j.message.ReusableMessageFactory; import org.apache.logging.log4j.message.SimpleMessage; import org.apache.logging.log4j.spi.AbstractLogger; -import org.apache.logging.log4j.util.LoaderUtil; import org.apache.logging.log4j.util.Strings; import org.apache.logging.log4j.util.Supplier; @@ -62,90 +57,42 @@ public class Logger extends AbstractLogger implements Supplier { private static final long serialVersionUID = 1L; - private static final String MESSAGE_FACTORY_PROPERTY_NAME = "log4j2.messageFactory"; - - private static final String FLOW_MESSAGE_FACTORY_PROPERTY_NAME = "log4j2.flowMessageFactory"; - /** * Config should be consistent across threads. */ protected volatile PrivateConfig privateConfig; - // FIXME: ditto to the above private final LoggerContext context; /** * Constructs an instance using the given {@link LoggerContext}, logger name, and {@link MessageFactory}. * - * @param context the {@link LoggerContext} this logger is associated with + * @param context The {@link LoggerContext} this logger is associated with, never {@code null}. + * @param name The logger name, never {@code null}. * @param messageFactory The message factory to be used. - * If null, first the {@value #MESSAGE_FACTORY_PROPERTY_NAME} property will be used to instantiate the message factory. - * If the property is missing and the {@code log4j2.enableThreadLocals} property is not {@code false}, {@link ReusableMessageFactory} will be used. - * Otherwise, we will fall back to {@link ParameterizedMessageFactory}. - * @param name the logger name + * Passing a {@code null} value is deprecated, but supported for backward compatibility. */ - protected Logger(final LoggerContext context, final String name, final MessageFactory messageFactory) { - this(context, name, messageFactory, null); + protected Logger(LoggerContext context, String name, MessageFactory messageFactory) { + this(context, name, messageFactory, LoggerContext.DEFAULT_FLOW_MESSAGE_FACTORY); } /** * The canonical constructor. * - * @param context the {@link LoggerContext} this logger is associated with + * @param context The {@link LoggerContext} this logger is associated with, never {@code null}. + * @param name The logger name, never {@code null}. * @param messageFactory The message factory to be used. - * If null, first the {@value #MESSAGE_FACTORY_PROPERTY_NAME} property will be used to instantiate the message factory. - * If the property is missing and the {@code log4j2.enableThreadLocals} property is not {@code false}, {@link ReusableMessageFactory} will be used. - * Otherwise, we will fall back to {@link ParameterizedMessageFactory}. + * Passing a {@code null} value is deprecated, but supported for backward compatibility. * @param flowMessageFactory The flow message factory to be used. - * If null, first the {@value #FLOW_MESSAGE_FACTORY_PROPERTY_NAME} property will be used to instantiate the flow message factory. - * If the property is missing, {@link DefaultFlowMessageFactory} will be used. - * @param name the logger name + * Passing a {@code null} value is deprecated, but supported for backward compatibility. */ protected Logger( - final LoggerContext context, - final String name, - final MessageFactory messageFactory, - final FlowMessageFactory flowMessageFactory) { - super(name, getEffectiveMessageFactory(messageFactory), getEffectiveFlowMessageFactory(flowMessageFactory)); + LoggerContext context, String name, MessageFactory messageFactory, FlowMessageFactory flowMessageFactory) { + super(name, messageFactory, flowMessageFactory); this.context = requireNonNull(context, "context"); this.privateConfig = new PrivateConfig(context.getConfiguration(), this); } - static MessageFactory getEffectiveMessageFactory(final MessageFactory messageFactory) { - return createInstanceFromFactoryProperty( - MessageFactory.class, - messageFactory, - MESSAGE_FACTORY_PROPERTY_NAME, - () -> Constants.ENABLE_THREADLOCALS - ? ReusableMessageFactory.INSTANCE - : ParameterizedMessageFactory.INSTANCE); - } - - private static FlowMessageFactory getEffectiveFlowMessageFactory(final FlowMessageFactory flowMessageFactory) { - return createInstanceFromFactoryProperty( - FlowMessageFactory.class, - flowMessageFactory, - FLOW_MESSAGE_FACTORY_PROPERTY_NAME, - () -> DefaultFlowMessageFactory.INSTANCE); - } - - private static V createInstanceFromFactoryProperty( - final Class instanceType, - final V providedInstance, - final String propertyName, - final java.util.function.Supplier fallbackInstanceSupplier) { - if (providedInstance != null) { - return providedInstance; - } - try { - return LoaderUtil.newCheckedInstanceOfProperty(propertyName, instanceType, fallbackInstanceSupplier); - } catch (final Exception error) { - final String message = - String.format("failed instantiating the class pointed by the `%s` property", propertyName); - throw new RuntimeException(message, error); - } - } - protected Object writeReplace() throws ObjectStreamException { return new LoggerProxy(getName(), getMessageFactory()); } diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/LoggerContext.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/LoggerContext.java index d084fd24843..1ed29fec586 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/LoggerContext.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/LoggerContext.java @@ -45,16 +45,22 @@ import org.apache.logging.log4j.core.impl.Log4jLogEvent; import org.apache.logging.log4j.core.jmx.Server; import org.apache.logging.log4j.core.util.Cancellable; +import org.apache.logging.log4j.core.util.Constants; import org.apache.logging.log4j.core.util.ExecutorServices; import org.apache.logging.log4j.core.util.NetUtils; import org.apache.logging.log4j.core.util.ShutdownCallbackRegistry; import org.apache.logging.log4j.core.util.internal.InternalLoggerRegistry; +import org.apache.logging.log4j.message.DefaultFlowMessageFactory; +import org.apache.logging.log4j.message.FlowMessageFactory; import org.apache.logging.log4j.message.MessageFactory; +import org.apache.logging.log4j.message.ParameterizedMessageFactory; +import org.apache.logging.log4j.message.ReusableMessageFactory; import org.apache.logging.log4j.spi.LoggerContextFactory; import org.apache.logging.log4j.spi.LoggerContextShutdownAware; import org.apache.logging.log4j.spi.LoggerContextShutdownEnabled; import org.apache.logging.log4j.spi.Terminable; import org.apache.logging.log4j.spi.ThreadContextMapFactory; +import org.apache.logging.log4j.util.LoaderUtil; import org.apache.logging.log4j.util.PropertiesUtil; /** @@ -74,14 +80,46 @@ public class LoggerContext extends AbstractLifeCycle */ public static final String PROPERTY_CONFIG = "config"; - private static final Configuration NULL_CONFIGURATION = new NullConfiguration(); + private static final String EXTERNAL_CONTEXT_KEY = "__EXTERNAL_CONTEXT_KEY__"; + private static final String MESSAGE_FACTORY_PROPERTY_NAME = "log4j2.messageFactory"; /** - * The default message factory to use while creating loggers, if none is provided. - * - * @see #2936 for the discussion on why we leak the message factory of the default logger and hardcode it here. + * The default message factory to use while creating loggers if the user provides none. + *

+ * To mitigate initialization problems as the one described in + * + * To mitigate initialization problems as the one described in + * propertyChangeListeners = new CopyOnWriteArrayList<>(); @@ -93,7 +131,6 @@ public class LoggerContext extends AbstractLifeCycle */ private volatile Configuration configuration = new DefaultConfiguration(); - private static final String EXTERNAL_CONTEXT_KEY = "__EXTERNAL_CONTEXT_KEY__"; private final ConcurrentMap externalMap = new ConcurrentHashMap<>(); private String contextName; private volatile URI configLocation; @@ -813,8 +850,15 @@ private Logger newInstance(final String name, final MessageFactory messageFactor return newInstance(this, name, messageFactory); } - // LOG4J2-151: changed visibility from private to protected - protected Logger newInstance(final LoggerContext ctx, final String name, final MessageFactory messageFactory) { - return new Logger(ctx, name, messageFactory); + /** + * Callback to create a new logger. + * + * @param context The {@link LoggerContext} this logger is associated with, never {@code null}. + * @param messageFactory The message factory to be used, never {@code null}. + * @param name The logger name, never {@code null}. + * @return A new logger instance. + */ + protected Logger newInstance(LoggerContext context, String name, MessageFactory messageFactory) { + return new Logger(context, name, messageFactory); } } diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java index 0378d010ccc..cfeac4a4fe3 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java @@ -85,17 +85,17 @@ public class AsyncLogger extends Logger implements EventTranslatorVararg + * This method is effectively package-private, since {@link AsyncLoggerDisruptor} is package-private. + *

+ * @param context The {@link LoggerContext} this logger is associated with, never {@code null}. + * @param name The logger name, never {@code null}. + * @param messageFactory The message factory to be used. + * Passing a {@code null} value is deprecated, but supported for backward compatibility. + * @param loggerDisruptor Helper class that logging can be delegated to. This object owns the Disruptor. */ public AsyncLogger( - final LoggerContext context, - final String name, - final MessageFactory messageFactory, - final AsyncLoggerDisruptor loggerDisruptor) { + LoggerContext context, String name, MessageFactory messageFactory, AsyncLoggerDisruptor loggerDisruptor) { super(context, name, messageFactory); this.loggerDisruptor = loggerDisruptor; includeLocation = privateConfig.loggerConfig.isIncludeLocation();