fix: make %ex behavior context-independent (#3919)

Historically, throwable pattern converters (`%ex`, `%xEx`, etc.) behaved in a context-sensitive way:

* If the **preceding formatter’s expansion** did not end with whitespace, the converter automatically inserted a space before rendering the exception.

In version `2.25.0`, this was changed to insert a **newline** instead of a space, but the behavior was still dependent on surrounding context.

#### What this change does

This PR removes the context-dependent behavior altogether and makes `%ex` expansion fully predictable, while remaining backward-compatible:

* When `%ex` is **added implicitly** because `alwaysWriteExceptions=true`:

  * If the pattern already ends with `%n`, a plain `%ex` is appended.
  * Otherwise, `%notEmpty{%n%ex}` is appended.
    This ensures exceptions are always clearly separated from the main log message by a newline, without adding extra characters when no exception is present.
* When `%ex` is **explicitly included** in the pattern by the user:

  * Its expansion is rendered exactly as written in the pattern.
  * It will **never** prepend a newline on its own.

#### Why

* Eliminates confusing context-sensitive behavior.
* Makes output consistent and predictable.
* Preserves legacy expectations by only modifying implicitly added `%ex`.

Closes #3873

Co-authored-by: Volkan Yazıcı <volkan@yazi.ci>

Author: ppkarwasz

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

@@ -16,13 +16,15 @@
  */
 package org.apache.logging.log4j.core.pattern;
 
+import static org.assertj.core.api.Assertions.assertThat;
 import static org.junit.jupiter.api.Assertions.assertEquals;
 import static org.junit.jupiter.api.Assertions.assertInstanceOf;
 import static org.junit.jupiter.api.Assertions.assertNotNull;
 import static org.junit.jupiter.api.Assertions.assertTrue;
 
 import java.util.Calendar;
 import java.util.List;
+import java.util.stream.Stream;
 import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.MarkerManager;
 import org.apache.logging.log4j.core.LogEvent;
@@ -40,6 +42,8 @@
 import org.apache.logging.log4j.util.Strings;
 import org.junit.jupiter.api.BeforeEach;
 import org.junit.jupiter.api.Test;
+import org.junit.jupiter.params.ParameterizedTest;
+import org.junit.jupiter.params.provider.MethodSource;
 
 class PatternParserTest {
 
@@ -98,6 +102,8 @@ void testCustomPattern() {
         assertNotNull(formatters);
         final StringMap mdc = ContextDataFactory.createContextData();
         mdc.putValue("loginId", "Fred");
+        // The line number of the Throwable definition
+        final int nextLineNumber = 107;
         final Throwable t = new Throwable();
         final StackTraceElement[] elements = t.getStackTrace();
         final Log4jLogEvent event = Log4jLogEvent.newBuilder() //
@@ -116,8 +122,9 @@ void testCustomPattern() {
             formatter.format(event, buf);
         }
         final String str = buf.toString();
-        final String expected = "INFO  [PatternParserTest        :101 ] - Hello, world" + Strings.LINE_SEPARATOR;
-        assertTrue(str.endsWith(expected), "Expected to end with: " + expected + ". Actual: " + str);
+        final String expected =
+                "INFO  [PatternParserTest        :" + nextLineNumber + " ] - Hello, world" + Strings.LINE_SEPARATOR;
+        assertThat(str).endsWith(expected);
     }
 
     @Test
@@ -369,6 +376,39 @@ void testClosingBracketButWrongPlace() {
         validateConverter(formatters, 1, "Date");
     }
 
+    static Stream<String> testAlwaysWriteExceptions_ensuresPrecededByNewline() {
+        return Stream.of("", "%m", "%n", "%m%n");
+    }
+
+    @ParameterizedTest
+    @MethodSource
+    void testAlwaysWriteExceptions_ensuresPrecededByNewline(final String pattern) {
+        final List<PatternFormatter> formatters = parser.parse(pattern, true, false, false);
+        assertNotNull(formatters);
+        if (pattern.endsWith("%n")) {
+            // Case 1: the original pattern ends with a new line, so the last converter is a ThrowablePatternConverter
+            assertThat(formatters).hasSizeGreaterThan(1);
+            final LogEventPatternConverter lastConverter =
+                    formatters.get(formatters.size() - 1).getConverter();
+            assertThat(lastConverter).isInstanceOf(ThrowablePatternConverter.class);
+            LogEventPatternConverter secondLastConverter =
+                    formatters.get(formatters.size() - 2).getConverter();
+            assertThat(secondLastConverter).isInstanceOf(LineSeparatorPatternConverter.class);
+        } else {
+            // Case 2: the original pattern does not end with a new line, so we add a composite converter
+            // that appends a new line and the exception if an exception is present.
+            assertThat(formatters).hasSizeGreaterThan(0);
+            final LogEventPatternConverter lastConverter =
+                    formatters.get(formatters.size() - 1).getConverter();
+            assertThat(lastConverter).isInstanceOf(VariablesNotEmptyReplacementConverter.class);
+            final List<PatternFormatter> nestedFormatters =
+                    ((VariablesNotEmptyReplacementConverter) lastConverter).formatters;
+            assertThat(nestedFormatters).hasSize(2);
+            assertThat(nestedFormatters.get(0).getConverter()).isInstanceOf(LineSeparatorPatternConverter.class);
+            assertThat(nestedFormatters.get(1).getConverter()).isInstanceOf(ThrowablePatternConverter.class);
+        }
+    }
+
     @Test
     void testExceptionWithFilters() {
         final List<PatternFormatter> formatters =

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

@@ -91,11 +91,11 @@ class StackTraceTest extends AbstractStackTraceTest {
 
         @Test
         @Override
-        void output_should_be_newline_prefixed() {
+        void output_should_not_be_newline_prefixed() {
             final String pattern = "%p" + patternPrefix;
             final String stackTrace = convert(pattern);
             final String expectedStart = String.format(
-                    "%s%n[CIRCULAR REFERENCE: %s", LEVEL, EXCEPTION.getClass().getCanonicalName());
+                    "%s[CIRCULAR REFERENCE: %s", LEVEL, EXCEPTION.getClass().getCanonicalName());
             assertThat(stackTrace).as("pattern=`%s`", pattern).startsWith(expectedStart);
         }
 

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

@@ -37,6 +37,7 @@
 import org.junit.jupiter.api.Test;
 import org.junit.jupiter.params.ParameterizedTest;
 import org.junit.jupiter.params.provider.MethodSource;
+import org.junitpioneer.jupiter.Issue;
 
 /**
  * {@link ThrowablePatternConverter} tests.
@@ -384,11 +385,12 @@ abstract static class AbstractStackTraceTest {
         }
 
         @Test
-        void output_should_be_newline_prefixed() {
+        @Issue("https://github.com/apache/logging-log4j2/issues/3873")
+        void output_should_not_be_newline_prefixed() {
             final String pattern = "%p" + patternPrefix;
             final String stackTrace = convert(pattern);
             final String expectedStart =
-                    String.format("%s%n%s", LEVEL, EXCEPTION.getClass().getCanonicalName());
+                    String.format("%s%s", LEVEL, EXCEPTION.getClass().getCanonicalName());
             assertThat(stackTrace).as("pattern=`%s`", pattern).startsWith(expectedStart);
         }
 

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

@@ -212,7 +212,26 @@ public List<PatternFormatter> parse(
             list.add(new PatternFormatter(pc, field));
         }
         if (alwaysWriteExceptions && !handlesThrowable) {
-            final LogEventPatternConverter pc = ThrowablePatternConverter.newInstance(config, new String[0]);
+            // We need to guarantee that an exception is always written,
+            // and that it is cleanly separated from the main log line by a newline.
+            final LogEventPatternConverter pc;
+            // Look at the last converter in the existing pattern.
+            final PatternFormatter lastFormatter = list.isEmpty() ? null : list.get(list.size() - 1);
+
+            if (lastFormatter == null || !(lastFormatter.getConverter() instanceof LineSeparatorPatternConverter)) {
+                // Case 1: The pattern does NOT already end with a newline.
+                // In this case, we append a composite converter `%notEmpty{%n%ex}`.
+                // - If no exception is present, it renders nothing (so the pattern behaves exactly as before).
+                // - If an exception is present, it renders a newline followed by the stack trace.
+                pc = VariablesNotEmptyReplacementConverter.newInstance(config, new String[] {"%n%ex"});
+            } else {
+                // Case 2: The pattern already ends with a newline.
+                // In this case, we only need to add `%ex`:
+                // - If no exception is present, nothing changes.
+                // - If an exception is present, it is written immediately after the newline already in the pattern.
+                pc = ThrowablePatternConverter.newInstance(config, Strings.EMPTY_ARRAY);
+            }
+            // Finally, add the chosen converter to the end of the pattern.
             list.add(new PatternFormatter(pc, FormattingInfo.getDefault()));
         }
         return list;

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

@@ -16,8 +16,6 @@
  */
 package org.apache.logging.log4j.core.pattern;
 
-import static org.apache.logging.log4j.util.Strings.LINE_SEPARATOR;
-
 import java.util.HashMap;
 import java.util.HashSet;
 import java.util.List;
@@ -55,7 +53,6 @@ public final void renderThrowable(
         if (maxLineCount > 0) {
             try {
                 C context = createContext(throwable);
-                ensureNewlineSuffix(buffer);
                 renderThrowable(buffer, throwable, context, new HashSet<>(), lineSeparator);
             } catch (final Exception error) {
                 if (error != MAX_LINE_COUNT_EXCEEDED) {
@@ -65,13 +62,6 @@ public final void renderThrowable(
         }
     }
 
-    private static void ensureNewlineSuffix(final StringBuilder buffer) {
-        final int bufferLength = buffer.length();
-        if (bufferLength > 0 && buffer.charAt(bufferLength - 1) != '\n') {
-            buffer.append(LINE_SEPARATOR);
-        }
-    }
-
     @SuppressWarnings("unchecked")
     C createContext(final Throwable throwable) {
         final Map<Throwable, Context.Metadata> metadataByThrowable = Context.Metadata.ofThrowable(throwable);

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

@@ -35,7 +35,8 @@
 @PerformanceSensitive("allocation")
 public final class VariablesNotEmptyReplacementConverter extends LogEventPatternConverter {
 
-    private final List<PatternFormatter> formatters;
+    // package private for testing
+    final List<PatternFormatter> formatters;
 
     /**
      * Constructs the converter.

log4j-taglib/src/test/java/org/apache/logging/log4j/taglib/CatchingTagTest.java

@@ -57,7 +57,7 @@ public void testDoEndTag() throws Exception {
         this.tag.setException(new Exception("This is a test."));
 
         assertEquals(Tag.EVAL_PAGE, this.tag.doEndTag(), "The return value is not correct.");
-        verify("Catching ERROR M-CATCHING[ EXCEPTION ] E" + LINE_SEPARATOR + "java.lang.Exception: This is a test.");
+        verify("Catching ERROR M-CATCHING[ EXCEPTION ] E-java.lang.Exception: This is a test.");
     }
 
     @Test
@@ -66,8 +66,7 @@ public void testDoEndTagLevelString() throws Exception {
         this.tag.setException(new RuntimeException("This is another test."));
 
         assertEquals(Tag.EVAL_PAGE, this.tag.doEndTag(), "The return value is not correct.");
-        verify("Catching INFO M-CATCHING[ EXCEPTION ] E" + LINE_SEPARATOR
-                + "java.lang.RuntimeException: This is another test.");
+        verify("Catching INFO M-CATCHING[ EXCEPTION ] E-java.lang.RuntimeException: This is another test.");
     }
 
     @Test
@@ -76,7 +75,7 @@ public void testDoEndTagLevelObject() throws Exception {
         this.tag.setException(new Error("This is the last test."));
 
         assertEquals(Tag.EVAL_PAGE, this.tag.doEndTag(), "The return value is not correct.");
-        verify("Catching WARN M-CATCHING[ EXCEPTION ] E" + LINE_SEPARATOR + "java.lang.Error: This is the last test.");
+        verify("Catching WARN M-CATCHING[ EXCEPTION ] E-java.lang.Error: This is the last test.");
     }
 
     private void verify(final String expected) {

log4j-taglib/src/test/java/org/apache/logging/log4j/taglib/EnterTagTest.java

@@ -54,7 +54,7 @@ public void setUp() {
     @Test
     public void testDoEndTag() throws Exception {
         assertEquals(Tag.EVAL_PAGE, this.tag.doEndTag(), "The return value is not correct.");
-        verify("Enter TRACE M-ENTER[ FLOW ] E");
+        verify("Enter TRACE M-ENTER[ FLOW ] E-");
     }
 
     @Test
@@ -63,7 +63,7 @@ public void testDoEndTagAttributes() throws Exception {
         this.tag.setDynamicAttribute(null, null, 5792);
 
         assertEquals(Tag.EVAL_PAGE, this.tag.doEndTag(), "The return value is not correct.");
-        verify("Enter params(log4j-test1.xml, 5792) TRACE M-ENTER[ FLOW ] E");
+        verify("Enter params(log4j-test1.xml, 5792) TRACE M-ENTER[ FLOW ] E-");
     }
 
     private void verify(final String expected) {

log4j-taglib/src/test/java/org/apache/logging/log4j/taglib/ExitTagTest.java

@@ -53,23 +53,23 @@ public void setUp() {
     @Test
     public void testDoEndTag() throws Exception {
         assertEquals(Tag.EVAL_PAGE, this.tag.doEndTag(), "The return value is not correct.");
-        verify("Exit TRACE M-EXIT[ FLOW ] E");
+        verify("Exit TRACE M-EXIT[ FLOW ] E-");
     }
 
     @Test
     public void testDoEndTagResult01() throws Exception {
         this.tag.setResult(CONFIG);
 
         assertEquals(Tag.EVAL_PAGE, this.tag.doEndTag(), "The return value is not correct.");
-        verify("Exit with(log4j-test1.xml) TRACE M-EXIT[ FLOW ] E");
+        verify("Exit with(log4j-test1.xml) TRACE M-EXIT[ FLOW ] E-");
     }
 
     @Test
     public void testDoEndTagResult02() throws Exception {
         this.tag.setResult(5792);
 
         assertEquals(Tag.EVAL_PAGE, this.tag.doEndTag(), "The return value is not correct.");
-        verify("Exit with(5792) TRACE M-EXIT[ FLOW ] E");
+        verify("Exit with(5792) TRACE M-EXIT[ FLOW ] E-");
     }
 
     private void verify(final String expected) {