Fix StringBuilder cache corruption on recursive access (#2275)

Author: vy

log4j-api-test/src/test/java/org/apache/logging/log4j/message/ParameterizedMessageRecursiveFormattingTestBase.java

@@ -0,0 +1,53 @@
+/*
+ * 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.message;
+
+import static org.assertj.core.api.Assertions.assertThat;
+
+import org.apache.logging.log4j.util.Constants;
+import org.junit.jupiter.api.Test;
+
+/**
+ * Tests {@link ParameterizedMessage#getFormattedMessage()} when formatted arguments causes another {@code ParameterizedMessage#getFormattedMessage()} (i.e., recursive) invocation.
+ */
+abstract class ParameterizedMessageRecursiveFormattingTestBase {
+
+    private final boolean threadLocalsEnabled;
+
+    ParameterizedMessageRecursiveFormattingTestBase(boolean threadLocalsEnabled) {
+        this.threadLocalsEnabled = threadLocalsEnabled;
+    }
+
+    @Test
+    void thread_locals_toggle_should_match() {
+        assertThat(Constants.ENABLE_THREADLOCALS).isEqualTo(threadLocalsEnabled);
+    }
+
+    @Test
+    void recursion_should_not_corrupt_formatting() {
+        final Object argInvokingParameterizedMessageFormatting = new Object() {
+            @Override
+            public String toString() {
+                return new ParameterizedMessage("bar {}", "baz").getFormattedMessage();
+            }
+        };
+        final ParameterizedMessage message =
+                new ParameterizedMessage("foo {}", argInvokingParameterizedMessageFormatting);
+        final String actualText = message.getFormattedMessage();
+        assertThat(actualText).isEqualTo("foo bar baz");
+    }
+}

log4j-api-test/src/test/java/org/apache/logging/log4j/message/ParameterizedMessageRecursiveFormattingWithThreadLocalsTest.java

@@ -0,0 +1,31 @@
+/*
+ * 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.message;
+
+import org.junitpioneer.jupiter.SetSystemProperty;
+
+/**
+ * {@link ParameterizedMessageRecursiveFormattingTestBase} subclass with thread locals disabled, i.e, with {@link StringBuilder} recycling.
+ */
+@SetSystemProperty(key = "log4j2.enable.threadlocals", value = "true")
+class ParameterizedMessageRecursiveFormattingWithThreadLocalsTest
+        extends ParameterizedMessageRecursiveFormattingTestBase {
+
+    ParameterizedMessageRecursiveFormattingWithThreadLocalsTest() {
+        super(true);
+    }
+}

log4j-api-test/src/test/java/org/apache/logging/log4j/message/ParameterizedMessageRecursiveFormattingWithoutThreadLocalsTest.java

@@ -0,0 +1,31 @@
+/*
+ * 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.message;
+
+import org.junitpioneer.jupiter.SetSystemProperty;
+
+/**
+ * {@link ParameterizedMessageRecursiveFormattingTestBase} subclass with thread locals disabled, i.e, no {@link StringBuilder} recycling.
+ */
+@SetSystemProperty(key = "log4j2.enable.threadlocals", value = "false")
+class ParameterizedMessageRecursiveFormattingWithoutThreadLocalsTest
+        extends ParameterizedMessageRecursiveFormattingTestBase {
+
+    ParameterizedMessageRecursiveFormattingWithoutThreadLocalsTest() {
+        super(false);
+    }
+}

log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterizedMessage.java

@@ -17,6 +17,7 @@
 package org.apache.logging.log4j.message;
 
 import static org.apache.logging.log4j.message.ParameterFormatter.analyzePattern;
+import static org.apache.logging.log4j.util.StringBuilders.trimToMaxSize;
 
 import com.google.errorprone.annotations.InlineMe;
 import java.io.IOException;
@@ -28,7 +29,6 @@
 import org.apache.logging.log4j.message.ParameterFormatter.MessagePatternAnalysis;
 import org.apache.logging.log4j.util.Constants;
 import org.apache.logging.log4j.util.StringBuilderFormattable;
-import org.apache.logging.log4j.util.StringBuilders;
 import org.apache.logging.log4j.util.internal.SerializationUtil;
 
 /**
@@ -44,10 +44,6 @@
  * {bar
  * {buzz}
  * </pre>
- * <p>
- * This class was originally written for <a href="http://lilithapp.com/">Lilith</a> by Jörn Huxhorn and licensed under the LGPL.
- * It has been relicensed here with his permission providing that this attribution remain.
- * </p>
  */
 public class ParameterizedMessage implements Message, StringBuilderFormattable {
 
@@ -83,9 +79,15 @@ public class ParameterizedMessage implements Message, StringBuilderFormattable {
 
     private static final long serialVersionUID = -665975803997290697L;
 
-    private static final ThreadLocal<StringBuilder> STRING_BUILDER_HOLDER = Constants.ENABLE_THREADLOCALS
-            ? ThreadLocal.withInitial(() -> new StringBuilder(Constants.MAX_REUSABLE_MESSAGE_SIZE))
-            : null;
+    private static final ThreadLocal<FormatBufferHolder> FORMAT_BUFFER_HOLDER_REF =
+            Constants.ENABLE_THREADLOCALS ? ThreadLocal.withInitial(FormatBufferHolder::new) : null;
+
+    private static final class FormatBufferHolder {
+
+        private final StringBuilder buffer = new StringBuilder(Constants.MAX_REUSABLE_MESSAGE_SIZE);
+
+        private boolean used = false;
+    }
 
     private final String pattern;
 
@@ -242,17 +244,26 @@ public Throwable getThrowable() {
     @Override
     public String getFormattedMessage() {
         if (formattedMessage == null) {
-            if (STRING_BUILDER_HOLDER != null) {
-                final StringBuilder buffer = STRING_BUILDER_HOLDER.get();
-                buffer.setLength(0);
-                formatTo(buffer);
-                formattedMessage = buffer.toString();
-                StringBuilders.trimToMaxSize(buffer, Constants.MAX_REUSABLE_MESSAGE_SIZE);
-            } else {
-                final StringBuilder buffer = new StringBuilder();
+            final FormatBufferHolder bufferHolder;
+            // If there isn't a format buffer to reuse
+            if (FORMAT_BUFFER_HOLDER_REF == null || (bufferHolder = FORMAT_BUFFER_HOLDER_REF.get()).used) {
+                final StringBuilder buffer = new StringBuilder(Constants.MAX_REUSABLE_MESSAGE_SIZE);
                 formatTo(buffer);
                 formattedMessage = buffer.toString();
             }
+            // If there is a format buffer to reuse
+            else {
+                bufferHolder.used = true;
+                final StringBuilder buffer = bufferHolder.buffer;
+                try {
+                    formatTo(buffer);
+                    formattedMessage = buffer.toString();
+                } finally {
+                    trimToMaxSize(buffer, Constants.MAX_REUSABLE_MESSAGE_SIZE);
+                    buffer.setLength(0);
+                    bufferHolder.used = false;
+                }
+            }
         }
         return formattedMessage;
     }
@@ -355,26 +366,28 @@ public static String identityToString(final Object obj) {
 
     @Override
     public String toString() {
-        return "ParameterizedMessage[messagePattern=" + pattern + ", stringArgs=" + Arrays.toString(args)
-                + ", throwable=" + throwable + ']';
+        // Avoid formatting arguments!
+        // It can cause recursion, which can become pretty unpleasant while troubleshooting.
+        return "ParameterizedMessage[messagePattern=" + pattern + ", argCount=" + args.length + ", throwableProvided="
+                + (throwable != null) + ']';
     }
 
     private void writeObject(final ObjectOutputStream out) throws IOException {
         out.defaultWriteObject();
         out.writeInt(args.length);
-        for (int i = 0; i < args.length; i++) {
-            SerializationUtil.writeWrappedObject(
-                    args[i] instanceof Serializable ? (Serializable) args[i] : String.valueOf(args[i]), out);
+        for (final Object arg : args) {
+            final Serializable serializableArg = arg instanceof Serializable ? (Serializable) arg : String.valueOf(arg);
+            SerializationUtil.writeWrappedObject(serializableArg, out);
         }
     }
 
     private void readObject(final ObjectInputStream in) throws IOException, ClassNotFoundException {
         SerializationUtil.assertFiltered(in);
         in.defaultReadObject();
-        final int length = in.readInt();
-        args = new Object[length];
-        for (int i = 0; i < args.length; i++) {
-            args[i] = SerializationUtil.readWrappedObject(in);
+        final int argCount = in.readInt();
+        args = new Object[argCount];
+        for (int argIndex = 0; argIndex < args.length; argIndex++) {
+            args[argIndex] = SerializationUtil.readWrappedObject(in);
         }
     }
 }

log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessage.java

@@ -16,11 +16,12 @@
  */
 package org.apache.logging.log4j.message;
 
+import static org.apache.logging.log4j.util.StringBuilders.trimToMaxSize;
+
 import java.util.Arrays;
 import org.apache.logging.log4j.message.ParameterFormatter.MessagePatternAnalysis;
 import org.apache.logging.log4j.util.Constants;
 import org.apache.logging.log4j.util.PerformanceSensitive;
-import org.apache.logging.log4j.util.StringBuilders;
 
 /**
  * Reusable parameterized message. This message is mutable and is not safe to be accessed or modified by multiple
@@ -32,13 +33,12 @@
 @PerformanceSensitive("allocation")
 public class ReusableParameterizedMessage implements ReusableMessage, ParameterVisitable, Clearable {
 
-    private static final int MIN_BUILDER_SIZE = 512;
     private static final int MAX_PARAMS = 10;
     private static final long serialVersionUID = 7800075879295123856L;
-    private transient ThreadLocal<StringBuilder> buffer; // non-static: LOG4J2-1583
 
     private String messagePattern;
     private final MessagePatternAnalysis patternAnalysis = new MessagePatternAnalysis();
+    private final StringBuilder formatBuffer = new StringBuilder(Constants.MAX_REUSABLE_MESSAGE_SIZE);
     private int argCount;
     private transient Object[] varargs;
     private transient Object[] params = new Object[MAX_PARAMS];
@@ -336,25 +336,13 @@ public Throwable getThrowable() {
      */
     @Override
     public String getFormattedMessage() {
-        final StringBuilder sb = getBuffer();
-        formatTo(sb);
-        final String result = sb.toString();
-        StringBuilders.trimToMaxSize(sb, Constants.MAX_REUSABLE_MESSAGE_SIZE);
-        return result;
-    }
-
-    private StringBuilder getBuffer() {
-        if (buffer == null) {
-            buffer = new ThreadLocal<>();
-        }
-        StringBuilder result = buffer.get();
-        if (result == null) {
-            final int currentPatternLength = messagePattern == null ? 0 : messagePattern.length();
-            result = new StringBuilder(Math.max(MIN_BUILDER_SIZE, currentPatternLength * 2));
-            buffer.set(result);
+        try {
+            formatTo(formatBuffer);
+            return formatBuffer.toString();
+        } finally {
+            trimToMaxSize(formatBuffer, Constants.MAX_REUSABLE_MESSAGE_SIZE);
+            formatBuffer.setLength(0);
         }
-        result.setLength(0);
-        return result;
     }
 
     @Override
@@ -374,8 +362,10 @@ ReusableParameterizedMessage reserve() {
 
     @Override
     public String toString() {
-        return "ReusableParameterizedMessage[messagePattern=" + getFormat() + ", stringArgs="
-                + Arrays.toString(getParameters()) + ", throwable=" + getThrowable() + ']';
+        // Avoid formatting arguments!
+        // It can cause recursion, which can become pretty unpleasant while troubleshooting.
+        return "ReusableParameterizedMessage[messagePattern=" + getFormat() + ", argCount=" + getParameterCount()
+                + ", throwableProvided=" + (getThrowable() != null) + ']';
     }
 
     @Override

log4j-api/src/main/java/org/apache/logging/log4j/util/Strings.java

@@ -16,6 +16,8 @@
  */
 package org.apache.logging.log4j.util;
 
+import static org.apache.logging.log4j.util.StringBuilders.trimToMaxSize;
+
 import java.util.Iterator;
 import java.util.Locale;
 import java.util.Objects;
@@ -28,7 +30,11 @@
 @InternalApi
 public final class Strings {
 
-    private static final ThreadLocal<StringBuilder> tempStr = ThreadLocal.withInitial(StringBuilder::new);
+    // 518 allows the `StringBuilder` to resize three times from its initial size.
+    // This should be sufficient for most use cases.
+    private static final int MAX_FORMAT_BUFFER_LENGTH = 518;
+
+    private static final ThreadLocal<StringBuilder> FORMAT_BUFFER_REF = ThreadLocal.withInitial(StringBuilder::new);
 
     /**
      * The empty string.
@@ -318,10 +324,11 @@ public static String concat(final String str1, final String str2) {
         } else if (isEmpty(str2)) {
             return str1;
         }
-        final StringBuilder sb = tempStr.get();
+        final StringBuilder sb = FORMAT_BUFFER_REF.get();
         try {
             return sb.append(str1).append(str2).toString();
         } finally {
+            trimToMaxSize(sb, MAX_FORMAT_BUFFER_LENGTH);
             sb.setLength(0);
         }
     }
@@ -338,13 +345,14 @@ public static String repeat(final String str, final int count) {
         if (count < 0) {
             throw new IllegalArgumentException("count");
         }
-        final StringBuilder sb = tempStr.get();
+        final StringBuilder sb = FORMAT_BUFFER_REF.get();
         try {
             for (int index = 0; index < count; index++) {
                 sb.append(str);
             }
             return sb.toString();
         } finally {
+            trimToMaxSize(sb, MAX_FORMAT_BUFFER_LENGTH);
             sb.setLength(0);
         }
     }

src/changelog/.2.x.x/fix_api_recursive_formatting.xml

@@ -0,0 +1,9 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<entry xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
+       xmlns="http://logging.apache.org/log4j/changelog"
+       xsi:schemaLocation="http://logging.apache.org/log4j/changelog https://logging.apache.org/log4j/changelog-0.1.3.xsd"
+       type="fixed">
+  <description format="asciidoc">
+    Fix `StringBuilder` cache corruption on recursive access
+  </description>
+</entry>