LOG4J2-3198: Log4j2 no longer formates lookups in messages by default

Lookups in messages are confusing, and muddy the line between logging APIs and implementation. Given a particular API, there's an expectation that a particular shape of call will result in specific results. However, lookups in messages can be passed into JUL and will result in resolved output in log4j formatted output, but not any other implementations despite no direct dependency on those implementations. There's also a cost to searching formatted message strings for particular escape sequences which define lookups. This feature is not used as far as we've been able to tell searching github and stackoverflow, so it's unnecessary for every log event in every application to burn several cpu cycles searching for the value.
apache · Nov 29, 2021 · 0f5bff1 · 0f5bff1
1 parent df0b5a1
commit 0f5bff1
Show file tree

Hide file tree

Showing 6 changed files with 103 additions and 8 deletions.
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/Constants.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/Constants.java
@@ -55,13 +55,17 @@ public final class Constants {
             "log4j.format.msg.async", false);
 
     /**
-     * LOG4J2-2109 if {@code true}, MessagePatternConverter will always operate as though
+     * LOG4J2-2109, LOG4J2-3198 By default, MessagePatternConverter will always operate as though
      * <pre>%m{nolookups}</pre> is configured.
+     * If overridden to {@code false}, lookups within message text are evaluated.
+     * Note that this will be handled in the layout regardless of the logging API used to produce messages,
+     * which may lead to undesired coupling. Checking every formatted message for lookup patterns has a
+     * measurable performance penalty, thus is recommended against.
      *
      * @since 2.10
      */
     public static final boolean FORMAT_MESSAGES_PATTERN_DISABLE_LOOKUPS = PropertiesUtil.getProperties().getBooleanProperty(
-            "log4j2.formatMsgNoLookups", false);
+            "log4j2.formatMsgNoLookups", true);
 
     /**
      * {@code true} if we think we are running in a web container, based on the boolean value of system property

diff --git a/...-core/src/test/java/org/apache/logging/log4j/core/layout/PatternLayoutLookupDateTest.java b/...-core/src/test/java/org/apache/logging/log4j/core/layout/PatternLayoutLookupDateTest.java
@@ -17,12 +17,14 @@
 package org.apache.logging.log4j.core.layout;
 
 import org.apache.logging.log4j.core.LoggerContext;
+import org.apache.logging.log4j.core.util.Constants;
 import org.apache.logging.log4j.junit.LoggerContextSource;
 import org.apache.logging.log4j.junit.Named;
 import org.apache.logging.log4j.test.appender.ListAppender;
 import org.junit.jupiter.api.Test;
 
 import static org.junit.jupiter.api.Assertions.assertFalse;
+import static org.junit.jupiter.api.Assumptions.assumeFalse;
 
 /**
  * See (LOG4J2-905) Ability to disable (date) lookup completely, compatibility issues with other libraries like camel.
@@ -34,6 +36,7 @@ public class PatternLayoutLookupDateTest {
 
     @Test
     public void testDateLookupInMessage(final LoggerContext context, @Named("List") final ListAppender listAppender) {
+        assumeFalse(Constants.FORMAT_MESSAGES_PATTERN_DISABLE_LOOKUPS);
         listAppender.clear();
         final String template = "${date:YYYY-MM-dd}";
         context.getLogger(PatternLayoutLookupDateTest.class.getName()).info(template);

diff --git a/...rc/test/java/org/apache/logging/log4j/core/pattern/MessagePatternConverterLookupTest.java b/...rc/test/java/org/apache/logging/log4j/core/pattern/MessagePatternConverterLookupTest.java
@@ -0,0 +1,76 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache license, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the license for the specific language governing permissions and
+ * limitations under the license.
+ */
+package org.apache.logging.log4j.core.pattern;
+
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.core.LogEvent;
+import org.apache.logging.log4j.core.config.Configuration;
+import org.apache.logging.log4j.core.config.builder.impl.DefaultConfigurationBuilder;
+import org.apache.logging.log4j.core.impl.Log4jLogEvent;
+import org.apache.logging.log4j.message.Message;
+import org.apache.logging.log4j.message.ParameterizedMessage;
+import org.junit.jupiter.api.AfterAll;
+import org.junit.jupiter.api.BeforeAll;
+import org.junit.jupiter.api.Test;
+
+import static org.junit.jupiter.api.Assertions.assertEquals;
+
+public class MessagePatternConverterLookupTest {
+
+    @BeforeAll
+    public static void beforeAll() {
+        System.setProperty("log4j2.formatMsgNoLookups", "false");
+    }
+
+    @AfterAll
+    public static void afterAll() {
+        System.clearProperty("log4j2.formatMsgNoLookups");
+    }
+
+    @Test
+    public void testLookup() {
+        final Configuration config = new DefaultConfigurationBuilder()
+                .addProperty("foo", "bar")
+                .build(true);
+        final MessagePatternConverter converter = MessagePatternConverter.newInstance(config, null);
+        final Message msg = new ParameterizedMessage("${foo}");
+        final LogEvent event = Log4jLogEvent.newBuilder() //
+                .setLoggerName("MyLogger") //
+                .setLevel(Level.DEBUG) //
+                .setMessage(msg).build();
+        final StringBuilder sb = new StringBuilder();
+        converter.format(event, sb);
+        assertEquals("bar", sb.toString(), "Unexpected result");
+    }
+
+    @Test
+    public void testDisabledLookup() {
+        final Configuration config = new DefaultConfigurationBuilder()
+                .addProperty("foo", "bar")
+                .build(true);
+        final MessagePatternConverter converter = MessagePatternConverter.newInstance(
+                config, new String[] {"nolookups"});
+        final Message msg = new ParameterizedMessage("${foo}");
+        final LogEvent event = Log4jLogEvent.newBuilder() //
+                .setLoggerName("MyLogger") //
+                .setLevel(Level.DEBUG) //
+                .setMessage(msg).build();
+        final StringBuilder sb = new StringBuilder();
+        converter.format(event, sb);
+        assertEquals("${foo}", sb.toString(), "Expected the raw pattern string without lookup");
+    }
+}
diff --git a/...core/src/test/java/org/apache/logging/log4j/core/pattern/MessagePatternConverterTest.java b/...core/src/test/java/org/apache/logging/log4j/core/pattern/MessagePatternConverterTest.java
@@ -76,12 +76,12 @@ public void testPatternAndParameterizedMessageDateLookup() {
     }
 
     @Test
-    public void testLookupEnabledByDefault() {
-        assertFalse(Constants.FORMAT_MESSAGES_PATTERN_DISABLE_LOOKUPS, "Expected lookups to be enabled");
+    public void testLookupDisabledByDefault() {
+        assertTrue(Constants.FORMAT_MESSAGES_PATTERN_DISABLE_LOOKUPS, "Expected lookups to be enabled");
     }
 
     @Test
-    public void testLookup() {
+    public void testDefaultDisabledLookup() {
         final Configuration config = new DefaultConfigurationBuilder()
                 .addProperty("foo", "bar")
                 .build(true);
@@ -93,7 +93,7 @@ public void testLookup() {
                 .setMessage(msg).build();
         final StringBuilder sb = new StringBuilder();
         converter.format(event, sb);
-        assertEquals("bar", sb.toString(), "Unexpected result");
+        assertEquals("${foo}", sb.toString(), "Unexpected result");
     }
 
     @Test

diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/pattern/RegexReplacementTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/pattern/RegexReplacementTest.java
@@ -18,6 +18,7 @@
 
 import org.apache.logging.log4j.ThreadContext;
 import org.apache.logging.log4j.core.LoggerContext;
+import org.apache.logging.log4j.core.util.Constants;
 import org.apache.logging.log4j.junit.LoggerContextSource;
 import org.apache.logging.log4j.junit.Named;
 import org.apache.logging.log4j.junit.UsingThreadContextMap;
@@ -28,6 +29,7 @@
 import java.util.List;
 
 import static org.junit.jupiter.api.Assertions.*;
+import static org.junit.jupiter.api.Assumptions.assumeFalse;
 
 @LoggerContextSource("log4j-replace.xml")
 @UsingThreadContextMap
@@ -55,10 +57,15 @@ public void testReplacement() {
         assertEquals(1, msgs.size(), "Incorrect number of messages. Should be 1 is " + msgs.size());
         assertTrue(
                 msgs.get(0).endsWith(EXPECTED), "Replacement failed - expected ending " + EXPECTED + " Actual " + msgs.get(0));
-        app.clear();
+
+    }
+
+    @Test
+    public void testMessageReplacement() {
+        assumeFalse(Constants.FORMAT_MESSAGES_PATTERN_DISABLE_LOOKUPS);
         ThreadContext.put("MyKey", "Apache");
         logger.error("This is a test for ${ctx:MyKey}");
-        msgs = app.getMessages();
+        List<String> msgs = app.getMessages();
         assertNotNull(msgs);
         assertEquals(1, msgs.size(), "Incorrect number of messages. Should be 1 is " + msgs.size());
         assertEquals("LoggerTest This is a test for Apache" + Strings.LINE_SEPARATOR, msgs.get(0));

diff --git a/src/changes/changes.xml b/src/changes/changes.xml
@@ -213,6 +213,11 @@
         Wrong subject on mail when it depends on the LogEvent
       </action>
       <!-- UPDATES -->
+      <action issue="LOG4J2-2025" dev="ckozak" type="update">
+        Update the default value of log4j2.formatMsgNoLookups to true, opting out of lookups within formatted messages
+        for cleaner API boundaries and reduced formatting overhead. The old behavior can be retained by setting the
+        log4j2.formatMsgNoLookups property to false.
+      </action>
       <action dev="rgoers" type="update">
         Update Spring framework to 5.3.13, Spring Boot to 2.5.7, and Spring Cloud to 2020.0.4.
       </action>