LOG4J2-3198: Log4j2 no longer formats 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.

Author: carterkozak

���log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/MessagePatternConverter.java

@@ -16,13 +16,13 @@
  */
 package org.apache.logging.log4j.core.pattern;
 
+import java.util.ArrayList;
+import java.util.List;
 import java.util.Locale;
 
 import org.apache.logging.log4j.core.LogEvent;
 import org.apache.logging.log4j.core.config.Configuration;
 import org.apache.logging.log4j.core.config.plugins.Plugin;
-import org.apache.logging.log4j.core.util.ArrayUtils;
-import org.apache.logging.log4j.core.util.Constants;
 import org.apache.logging.log4j.core.util.Loader;
 import org.apache.logging.log4j.message.Message;
 import org.apache.logging.log4j.message.MultiformatMessage;
@@ -39,17 +39,18 @@
 @PerformanceSensitive("allocation")
 public class MessagePatternConverter extends LogEventPatternConverter {
 
+    private static final String LOOKUPS = "lookups";
     private static final String NOLOOKUPS = "nolookups";
 
     private MessagePatternConverter() {
         super("Message", "message");
     }
 
-    private static int loadNoLookups(final String[] options) {
+    private static int loadLookups(final String[] options) {
         if (options != null) {
             for (int i = 0; i < options.length; i++) {
                 final String option = options[i];
-                if (NOLOOKUPS.equalsIgnoreCase(option)) {
+                if (LOOKUPS.equalsIgnoreCase(option)) {
                     return i;
                 }
             }
@@ -86,14 +87,13 @@ private static TextRenderer loadMessageRenderer(final String[] options) {
      * @return instance of pattern converter.
      */
     public static MessagePatternConverter newInstance(final Configuration config, final String[] options) {
-        int noLookupsIdx = loadNoLookups(options);
-        boolean noLookups = Constants.FORMAT_MESSAGES_PATTERN_DISABLE_LOOKUPS || noLookupsIdx >= 0;
-        String[] formats = noLookupsIdx >= 0 ? ArrayUtils.remove(options, noLookupsIdx) : options;
-        TextRenderer textRenderer = loadMessageRenderer(noLookupsIdx >= 0 ? ArrayUtils.remove(options, noLookupsIdx) : options);
+        boolean lookups = loadLookups(options) >= 0;
+        String[] formats = withoutLookupOptions(options);
+        TextRenderer textRenderer = loadMessageRenderer(formats);
         MessagePatternConverter result = formats == null || formats.length == 0
                 ? SimpleMessagePatternConverter.INSTANCE
                 : new FormattedMessagePatternConverter(formats);
-        if (!noLookups && config != null) {
+        if (lookups && config != null) {
             result = new LookupMessagePatternConverter(result, config);
         }
         if (textRenderer != null) {
@@ -102,6 +102,19 @@ public static MessagePatternConverter newInstance(final Configuration config, fi
         return result;
     }
 
+    private static String[] withoutLookupOptions(final String[] options) {
+        if (options == null || options.length == 0) {
+            return options;
+        }
+        List<String> results = new ArrayList<>(options.length);
+        for (String option : options) {
+            if (!LOOKUPS.equalsIgnoreCase(option) && !NOLOOKUPS.equalsIgnoreCase(option)) {
+                results.add(option);
+            }
+        }
+        return results.toArray(new String[0]);
+    }
+
     @Override
     public void format(final LogEvent event, final StringBuilder toAppendTo) {
         throw new UnsupportedOperationException();

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
-     * <pre>%m{nolookups}</pre> is configured.
+     * LOG4J2-3198 property which used to globally opt out of lookups in pattern layout message text, however
+     * this is the default and this property is no longer read.
+     *
+     * Deprecated in 2.15.
      *
      * @since 2.10
+     * @deprecated no longer used, lookups are only used when {@code %m{lookups}} is specified
      */
+    @Deprecated
     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

���log4j-core/src/test/java/org/apache/logging/log4j/core/layout/PatternLayoutLookupDateTest.java

@@ -29,7 +29,7 @@
  *
  * This shows the behavior this user wants to disable.
  */
-@LoggerContextSource("log4j-list.xml")
+@LoggerContextSource("log4j-list-lookups.xml")
 public class PatternLayoutLookupDateTest {
 
     @Test

log4j-core/src/test/java/org/apache/logging/log4j/core/layout/PatternLayoutNoLookupDateTest.java

@@ -26,7 +26,7 @@
 /**
  * See (LOG4J2-905) Ability to disable (date) lookup completely, compatibility issues with other libraries like camel.
  */
-@LoggerContextSource("log4j-list-nolookups.xml")
+@LoggerContextSource("log4j-list.xml")
 public class PatternLayoutNoLookupDateTest {
 
     @Test

log4j-core/src/test/java/org/apache/logging/log4j/core/pattern/MessagePatternConverterTest.java

@@ -22,7 +22,6 @@
 import org.apache.logging.log4j.core.config.DefaultConfiguration;
 import org.apache.logging.log4j.core.config.builder.impl.DefaultConfigurationBuilder;
 import org.apache.logging.log4j.core.impl.Log4jLogEvent;
-import org.apache.logging.log4j.core.util.Constants;
 import org.apache.logging.log4j.message.Message;
 import org.apache.logging.log4j.message.ParameterizedMessage;
 import org.apache.logging.log4j.message.SimpleMessage;
@@ -76,12 +75,7 @@ public void testPatternAndParameterizedMessageDateLookup() {
     }
 
     @Test
-    public void testLookupEnabledByDefault() {
-        assertFalse(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 +87,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
@@ -113,6 +107,23 @@ public void testDisabledLookup() {
         assertEquals("${foo}", sb.toString(), "Expected the raw pattern string without lookup");
     }
 
+    @Test
+    public void testLookup() {
+        final Configuration config = new DefaultConfigurationBuilder()
+                .addProperty("foo", "bar")
+                .build(true);
+        final MessagePatternConverter converter =
+                MessagePatternConverter.newInstance(config, new String[] {"lookups"});
+        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 testPatternWithConfiguration() {
         final Configuration config = new DefaultConfiguration();

log4j-core/src/test/java/org/apache/logging/log4j/core/pattern/RegexReplacementTest.java

@@ -16,6 +16,12 @@
  */
 package org.apache.logging.log4j.core.pattern;
 
+import static org.junit.jupiter.api.Assertions.assertEquals;
+import static org.junit.jupiter.api.Assertions.assertNotNull;
+import static org.junit.jupiter.api.Assertions.assertTrue;
+
+import java.util.List;
+
 import org.apache.logging.log4j.ThreadContext;
 import org.apache.logging.log4j.core.LoggerContext;
 import org.apache.logging.log4j.junit.LoggerContextSource;
@@ -25,10 +31,6 @@
 import org.apache.logging.log4j.util.Strings;
 import org.junit.jupiter.api.Test;
 
-import java.util.List;
-
-import static org.junit.jupiter.api.Assertions.*;
-
 @LoggerContextSource("log4j-replace.xml")
 @UsingThreadContextMap
 public class RegexReplacementTest {
@@ -55,10 +57,14 @@ 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() {
         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));

log4j-core/src/test/resources/log4j-list-nolookups.xml renamed to log4j-core/src/test/resources/log4j-list-lookups.xml

@@ -18,7 +18,7 @@
 <Configuration status="WARN">
   <Appenders>
     <List name="List">
-      <PatternLayout pattern="[%-5level] %c{1.} %msg{ansi}{nolookups}%n" />
+      <PatternLayout pattern="[%-5level] %c{1.} %msg{ansi}{lookups}%n" />
     </List>
   </Appenders>
   <Loggers>

log4j-core/src/test/resources/log4j-replace.xml

@@ -21,12 +21,12 @@
     <List name="List">
        <PatternLayout>
          <replace regex="\." replacement="/"/>
-         <Pattern>%logger %msg%n</Pattern>
+         <Pattern>%logger %msg{lookups}%n</Pattern>
       </PatternLayout>
     </List>
     <List name="List2">
        <PatternLayout>
-         <Pattern>%replace{%logger %C{1.} %msg%n}{\.}{/}</Pattern>
+         <Pattern>%replace{%logger %C{1.} %msg{lookups}%n}{\.}{/}</Pattern>
       </PatternLayout>
     </List>
   </Appenders>

src/changes/changes.xml

@@ -31,6 +31,12 @@
     -->
     <release version="2.15.0" date="2021-MM-DD" description="GA Release 2.15.0">
       <!-- ADDS -->
+      <action issue="LOG4J2-3198" dev="ckozak" type="add">
+        Pattern layout no longer enables lookups within message text by default for cleaner API boundaries and reduced
+        formatting overhead. The old 'log4j2.formatMsgNoLookups' which enabled this behavior has been removed as well
+        as the 'nolookups' message pattern converter option. The old behavior can be enabled on a per-pattern basis
+        using '%m{lookups}'.
+      </action>
       <action issue="LOG4J2-3194" dev="rgoers" type="add" due-to="markuss">
         Allow fractional attributes for size attribute of SizeBsaedTriggeringPolicy.
       </action>

src/site/xdoc/manual/configuration.xml.vm

@@ -1264,14 +1264,13 @@ rootLogger.appenderRef.stdout.ref = STDOUT
             <code>app.properties</code> would be used as the default value.
           </p>
         </subsection>
-        <a name="DisablingMessagePatternLookups"/>
-        <subsection name="Disables Message Pattern Lookups">
+        <a name="EnablingMessagePatternLookups"/>
+        <subsection name="Enabling Message Pattern Lookups">
         <p>
-          A message is processed (by default) by lookups, for example if you defined
+          A message is processed (by default) without using lookups, for example if you defined
           <code> &lt;Property name="foo.bar">FOO_BAR &lt;/Property></code>, then <code>logger.info("${foo.bar}")</code>
-          will output <code>FOO_BAR</code> instead of <code>${dollar}{foo.bar}</code>. You could disable message pattern
-          lookups globally by setting system property <code>log4j2.formatMsgNoLookups</code> to true,
-          or defining message pattern using %m{nolookups}.
+          will output <code>${dollar}{foo.bar}</code> instead of <code>FOO_BAR</code>. You could enable message pattern
+          lookups by defining message pattern using %m{lookups}.
         </p>
         </subsection>
         <a name="RuntimeLookup"/>
@@ -2672,16 +2671,6 @@ public class AwesomeTest {
     <td>Prints a stacktrace to the <a href="#StatusMessages">status logger</a> at DEBUG level
     when the LoggerContext is started. For debug purposes.</td>
   </tr>
-  <tr>
-      <td><a name="formatMsgNoLookups"/>log4j2.formatMsgNoLookups
-        <br />
-        (<a name="log4j2.formatMsgNoLookups" />log4j2.formatMsgNoLookups)
-      </td>
-      <td>FORMAT_MESSAGES_PATTERN_DISABLE_LOOKUPS</td>
-      <td>false</td>
-      <td>Disables message pattern lookups globally when set to <tt>true</tt>.
-          This is equivalent to defining all message patterns using <tt>%m{nolookups}</tt>.</td>
-  </tr>
   <tr>
     <td><a name="log4j2.trustStoreLocation "/>log4j2.trustStoreLocation</td>
     <td>LOG4J_TRUST_STORE_LOCATION</td>