Improve implementations of LogEvent.toImmutable() and ReusableMessage.memento() (#3171)

The implementations of `LogEvent.toImmutable()` either use serialization or one of the `Log4jLogEvent.Builder` constructors and custom per class code.

This PR:

- Redirects all implementation of `LogEvent.toImmutable` to the `Builder(LogEvent)` constructor (except `Log4jLogEvent.toImmutable()`)
- Improve the constructor to create really immutable and thread-safe instances.
- Removes the usage of `ThrowableProxy` for purposes not related to serialization.
- Fixes some implementations of `ReusableMessage.memento()`.
- Uses `ReusableMessage.memento()` instead of `ImmutableMessage` where
  applicable.

Author: ppkarwasz

log4j-1.2-api/src/main/java/org/apache/log4j/rewrite/MapRewritePolicy.java

@@ -105,7 +105,6 @@ public LoggingEvent rewrite(final LoggingEvent source) {
                         .setThrown(source.getThrowableInformation().getThrowable())
                         .setTimeMillis(source.getTimeStamp())
                         .setNanoTime(0)
-                        .setThrownProxy(null)
                         .build();
             }
             return new LogEventAdapter(event);

log4j-1.2-api/src/main/java/org/apache/log4j/rewrite/PropertyRewritePolicy.java

@@ -110,7 +110,6 @@ public LoggingEvent rewrite(final LoggingEvent source) {
                         .setThrown(source.getThrowableInformation().getThrowable())
                         .setTimeMillis(source.getTimeStamp())
                         .setNanoTime(0)
-                        .setThrownProxy(null)
                         .build();
             }
             return new LogEventAdapter(event);

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

@@ -128,7 +128,11 @@ public <S> void forEachParameter(final ParameterConsumer<S> action, final S stat
 
     @Override
     public Message memento() {
-        return new ObjectMessage(obj);
+        Message message = new ObjectMessage(obj);
+        // Since `toString()` methods are not always pure functions and might depend on the thread and other context
+        // values, we format the message and cache the result.
+        message.getFormattedMessage();
+        return message;
     }
 
     /**

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

@@ -114,7 +114,11 @@ public <S> void forEachParameter(final ParameterConsumer<S> action, final S stat
 
     @Override
     public Message memento() {
-        return new ParameterizedMessage(messagePattern, getTrimmedParams());
+        Message message = new ParameterizedMessage(messagePattern, getTrimmedParams());
+        // Since `toString()` methods are not always pure functions and might depend on the thread and other context
+        // values, we format the message and cache the result.
+        message.getFormattedMessage();
+        return message;
     }
 
     private void init(final String messagePattern, final int argCount, final Object[] args) {

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

@@ -85,7 +85,11 @@ public <S> void forEachParameter(final ParameterConsumer<S> action, final S stat
 
     @Override
     public Message memento() {
-        return new SimpleMessage(charSequence);
+        SimpleMessage message = new SimpleMessage(charSequence);
+        // Since `toString()` methods are not always pure functions and might depend on the thread and other context
+        // values, we format the message and cache the result.
+        message.getFormattedMessage();
+        return message;
     }
 
     // CharSequence impl

log4j-core-test/src/main/java/org/apache/logging/log4j/core/test/appender/ListAppender.java

@@ -35,7 +35,6 @@
 import org.apache.logging.log4j.core.config.plugins.PluginBuilderFactory;
 import org.apache.logging.log4j.core.config.plugins.PluginElement;
 import org.apache.logging.log4j.core.config.plugins.validation.constraints.Required;
-import org.apache.logging.log4j.core.impl.MutableLogEvent;
 import org.apache.logging.log4j.core.layout.SerializedLayout;
 import org.awaitility.Awaitility;
 
@@ -121,12 +120,7 @@ public ListAppender(
     public void append(final LogEvent event) {
         final Layout<? extends Serializable> layout = getLayout();
         if (layout == null) {
-            if (event instanceof MutableLogEvent) {
-                // must take snapshot or subsequent calls to logger.log() will modify this event
-                events.add(((MutableLogEvent) event).createMemento());
-            } else {
-                events.add(event);
-            }
+            events.add(event.toImmutable());
         } else if (layout instanceof SerializedLayout) {
             final byte[] header = layout.getHeader();
             final byte[] content = layout.toByteArray(event);

log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/BlockingAppender.java

@@ -33,7 +33,6 @@
 import org.apache.logging.log4j.core.config.plugins.PluginElement;
 import org.apache.logging.log4j.core.config.plugins.PluginFactory;
 import org.apache.logging.log4j.core.config.plugins.validation.constraints.Required;
-import org.apache.logging.log4j.core.impl.Log4jLogEvent;
 
 /**
  * Appender that can be halted and resumed, for testing queue-full scenarios.
@@ -58,7 +57,7 @@ public void append(final LogEvent event) {
         // may be a reusable event, make a copy, don't keep a reference to the original event
         final List<LogEvent> events = logEvents;
         if (events != null) {
-            events.add(Log4jLogEvent.createMemento(event));
+            events.add(event.toImmutable());
         }
 
         if (countDownLatch == null) {

log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java

@@ -28,6 +28,7 @@
 import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.Marker;
 import org.apache.logging.log4j.MarkerManager;
+import org.apache.logging.log4j.ThreadContext;
 import org.apache.logging.log4j.ThreadContext.ContextStack;
 import org.apache.logging.log4j.core.LogEvent;
 import org.apache.logging.log4j.core.impl.ThrowableProxy;
@@ -201,7 +202,7 @@ void testSerializationDeserialization() {
         final Level level = Level.TRACE;
         final Message data = new SimpleMessage("message");
         final Throwable t = new InternalError("not a real error");
-        final ContextStack contextStack = null;
+        final ContextStack contextStack = ThreadContext.getImmutableStack();
         final String threadName = "main";
         final StackTraceElement location = null;
         evt.setValues(
@@ -222,25 +223,31 @@ void testSerializationDeserialization() {
                 new DummyNanoClock(1));
         ((StringMap) evt.getContextData()).putValue("key", "value");
 
-        final RingBufferLogEvent other = SerialUtil.deserialize(SerialUtil.serialize(evt));
-        assertThat(other.getLoggerName()).isEqualTo(loggerName);
-        assertThat(other.getMarker()).isEqualTo(marker);
-        assertThat(other.getLoggerFqcn()).isEqualTo(fqcn);
-        assertThat(other.getLevel()).isEqualTo(level);
-        assertThat(other.getMessage()).isEqualTo(data);
-        assertThat(other.getThrown()).isNull();
-        assertThat(other.getThrownProxy()).isEqualTo(new ThrowableProxy(t));
-        assertThat(other.getContextData()).isEqualTo(evt.getContextData());
-        assertThat(other.getContextStack()).isEqualTo(contextStack);
-        assertThat(other.getThreadName()).isEqualTo(threadName);
-        assertThat(other.getSource()).isEqualTo(location);
-        assertThat(other.getTimeMillis()).isEqualTo(12345);
-        assertThat(other.getInstant().getNanoOfMillisecond()).isEqualTo(678);
+        final LogEvent other = SerialUtil.deserialize(SerialUtil.serialize(evt));
+        assertThat(other.getLoggerName()).as("Logger name").isEqualTo(loggerName);
+        assertThat(other.getMarker()).as("Marker").isEqualTo(marker);
+        assertThat(other.getLoggerFqcn())
+                .as("Fully qualified class name of logger implementation")
+                .isEqualTo(fqcn);
+        assertThat(other.getLevel()).as("Log event level").isEqualTo(level);
+        assertThat(other.getMessage()).as("Log event message").isEqualTo(data);
+        assertThat(other.getThrown()).as("Thrown exception").isNull();
+        assertThat(other.getThrownProxy())
+                .as("Serialization proxy for thrown exception")
+                .isEqualTo(new ThrowableProxy(t));
+        assertThat(other.getContextData()).as("Context data map").isEqualTo(evt.getContextData());
+        assertThat(other.getContextStack()).as("Context data stack").isEqualTo(contextStack);
+        assertThat(other.getThreadName()).as("Thread name").isEqualTo(threadName);
+        assertThat(other.getSource()).as("Log event location").isEqualTo(location);
+        assertThat(other.getTimeMillis()).as("Log event timestamp in millis").isEqualTo(12345);
+        assertThat(other.getInstant().getNanoOfMillisecond())
+                .as("Log event timestamp in nanos of millis")
+                .isEqualTo(678);
     }
 
     @SuppressWarnings("deprecation")
     @Test
-    void testCreateMementoReturnsCopy() {
+    void testToImmutableReturnsCopy() {
         final RingBufferLogEvent evt = new RingBufferLogEvent();
         final String loggerName = "logger.name";
         final Marker marker = MarkerManager.getMarker("marked man");
@@ -269,7 +276,7 @@ void testCreateMementoReturnsCopy() {
                 new DummyNanoClock(1));
         ((StringMap) evt.getContextData()).putValue("key", "value");
 
-        final LogEvent actual = evt.createMemento();
+        final LogEvent actual = evt.toImmutable();
         assertThat(actual.getLoggerName()).isEqualTo(evt.getLoggerName());
         assertThat(actual.getMarker()).isEqualTo(evt.getMarker());
         assertThat(actual.getLoggerFqcn()).isEqualTo(evt.getLoggerFqcn());
@@ -288,7 +295,7 @@ void testCreateMementoReturnsCopy() {
     }
 
     @Test
-    void testCreateMementoRetainsParametersAndFormat() {
+    void testToImmutableRetainsParametersAndFormat() {
         final RingBufferLogEvent evt = new RingBufferLogEvent();
         // Initialize the event with parameters
         evt.swapParameters(new Object[10]);
@@ -321,7 +328,7 @@ void testCreateMementoRetainsParametersAndFormat() {
                     new DummyNanoClock(1));
             ((StringMap) evt.getContextData()).putValue("key", "value");
 
-            final Message actual = evt.createMemento().getMessage();
+            final Message actual = evt.toImmutable().getMessage();
             assertThat(actual.getFormat()).isEqualTo("Hello {}!");
             assertThat(actual.getParameters()).isEqualTo(new String[] {"World"});
             assertThat(actual.getFormattedMessage()).isEqualTo("Hello World!");

log4j-core-test/src/test/java/org/apache/logging/log4j/core/impl/MutableLogEventTest.java

@@ -137,7 +137,7 @@ void testInitFromReusableCopiesFormatString() {
         assertEquals("msg in a bottle", memento.getFormattedMessage(), "formatted");
         assertArrayEquals(new String[] {"bottle"}, memento.getParameters(), "parameters");
 
-        final Message eventMementoMessage = mutable.createMemento().getMessage();
+        final Message eventMementoMessage = mutable.toImmutable().getMessage();
         assertEquals("msg in a {}", eventMementoMessage.getFormat(), "format");
         assertEquals("msg in a bottle", eventMementoMessage.getFormattedMessage(), "formatted");
         assertArrayEquals(new String[] {"bottle"}, eventMementoMessage.getParameters(), "parameters");

log4j-core-test/src/test/java/org/apache/logging/log4j/core/net/SmtpManagerTest.java

@@ -16,16 +16,13 @@
  */
 package org.apache.logging.log4j.core.net;
 
-import static org.hamcrest.CoreMatchers.instanceOf;
-import static org.hamcrest.CoreMatchers.is;
-import static org.hamcrest.MatcherAssert.assertThat;
+import static org.assertj.core.api.Assertions.assertThat;
 import static org.junit.jupiter.api.Assertions.assertEquals;
 
 import org.apache.logging.log4j.core.LogEvent;
 import org.apache.logging.log4j.core.appender.SmtpAppender;
 import org.apache.logging.log4j.core.async.RingBufferLogEvent;
 import org.apache.logging.log4j.core.impl.Log4jLogEvent;
-import org.apache.logging.log4j.core.impl.MementoMessage;
 import org.apache.logging.log4j.core.impl.MutableLogEvent;
 import org.apache.logging.log4j.core.util.ClockFactory;
 import org.apache.logging.log4j.core.util.DummyNanoClock;
@@ -72,17 +69,14 @@ private void testAdd(final LogEvent event) {
                 .setBufferSize(10)
                 .build();
         final MailManager mailManager = appender.getManager();
-        assertThat("is instance of SmtpManager", mailManager instanceof SmtpManager);
+        assertThat(mailManager).isInstanceOf(SmtpManager.class);
         final SmtpManager smtpManager = (SmtpManager) mailManager;
         smtpManager.removeAllBufferedEvents(); // in case this smtpManager is reused
         smtpManager.add(event);
 
         final LogEvent[] bufferedEvents = smtpManager.removeAllBufferedEvents();
-        assertThat("unexpected number of buffered events", bufferedEvents.length, is(1));
-        assertThat(
-                "expected the immutable version of the event to be buffered",
-                bufferedEvents[0].getMessage(),
-                is(instanceOf(MementoMessage.class)));
+        assertThat(bufferedEvents).as("Buffered events").hasSize(1);
+        assertThat(bufferedEvents[0].getMessage()).as("Immutable message").isNotInstanceOf(ReusableMessage.class);
     }
 
     // LOG4J2-3172: make sure existing protections are not violated