From d04f1aa97139af9b05c82d333969caab2ee7ad83 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Volkan=20Yaz=C4=B1c=C4=B1?= Date: Wed, 24 Jan 2024 11:07:13 +0100 Subject: [PATCH] Fix forgotten `threadName` field in `RingBufferLogEvent#clear()` (#2234) --- .../core/async/RingBufferLogEventTest.java | 220 ++++++++++++------ .../log4j/core/async/RingBufferLogEvent.java | 33 +-- .../.2.x.x/fix_RingBufferLogEvent_clear.xml | 10 + 3 files changed, 176 insertions(+), 87 deletions(-) create mode 100644 src/changelog/.2.x.x/fix_RingBufferLogEvent_clear.xml diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java index 17efc14d464..a1ae1efe31c 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java @@ -16,15 +16,13 @@ */ package org.apache.logging.log4j.core.async; -import static org.hamcrest.CoreMatchers.sameInstance; -import static org.junit.Assert.assertArrayEquals; -import static org.junit.Assert.assertEquals; -import static org.junit.Assert.assertFalse; -import static org.junit.Assert.assertNotNull; -import static org.junit.Assert.assertNull; -import static org.junit.Assert.assertThat; -import static org.junit.Assert.assertTrue; -import static org.junit.Assert.fail; +import static org.assertj.core.api.Assertions.as; +import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.assertThatCode; +import static org.assertj.core.api.Assertions.fail; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.verifyNoMoreInteractions; import java.io.ByteArrayInputStream; import java.io.ByteArrayOutputStream; @@ -38,39 +36,39 @@ import org.apache.logging.log4j.ThreadContext.ContextStack; import org.apache.logging.log4j.core.LogEvent; import org.apache.logging.log4j.core.impl.ThrowableProxy; -import org.apache.logging.log4j.core.test.categories.AsyncLoggers; import org.apache.logging.log4j.core.time.internal.FixedPreciseClock; +import org.apache.logging.log4j.core.util.Clock; import org.apache.logging.log4j.core.util.DummyNanoClock; +import org.apache.logging.log4j.core.util.NanoClock; import org.apache.logging.log4j.message.Message; import org.apache.logging.log4j.message.ReusableMessageFactory; import org.apache.logging.log4j.message.SimpleMessage; import org.apache.logging.log4j.spi.MutableThreadContextStack; import org.apache.logging.log4j.util.FilteredObjectInputStream; import org.apache.logging.log4j.util.StringMap; -import org.junit.Assert; -import org.junit.Test; -import org.junit.experimental.categories.Category; +import org.assertj.core.api.InstanceOfAssertFactories; +import org.junit.jupiter.api.Tag; +import org.junit.jupiter.api.Test; /** * Tests the RingBufferLogEvent class. */ -@Category(AsyncLoggers.class) -public class RingBufferLogEventTest { +@Tag("async") +class RingBufferLogEventTest { @Test - public void testToImmutable() { + void testToImmutable() { final LogEvent logEvent = new RingBufferLogEvent(); - Assert.assertNotSame(logEvent, logEvent.toImmutable()); + assertThat(logEvent).isNotSameAs(logEvent.toImmutable()); } /** - * @see LOG4J2-2816 + * Reproduces LOG4J2-2816. */ @Test - public void testIsPopulated() { + void testIsPopulated() { final RingBufferLogEvent evt = new RingBufferLogEvent(); - - assertFalse(evt.isPopulated()); + assertThat(evt.isPopulated()).isFalse(); final String loggerName = null; final Marker marker = null; @@ -98,15 +96,15 @@ public void testIsPopulated() { new FixedPreciseClock(), new DummyNanoClock(1)); - assertTrue(evt.isPopulated()); + assertThat(evt.isPopulated()).isTrue(); evt.clear(); - assertFalse(evt.isPopulated()); + assertThat(evt.isPopulated()).isFalse(); } @Test - public void testGetLevelReturnsOffIfNullLevelSet() { + void testGetLevelReturnsOffIfNullLevelSet() { final RingBufferLogEvent evt = new RingBufferLogEvent(); final String loggerName = null; final Marker marker = null; @@ -133,11 +131,11 @@ public void testGetLevelReturnsOffIfNullLevelSet() { location, new FixedPreciseClock(), new DummyNanoClock(1)); - assertEquals(Level.OFF, evt.getLevel()); + assertThat(evt.getLevel()).isEqualTo(Level.OFF); } @Test - public void testGetMessageReturnsNonNullMessage() { + void testGetMessageReturnsNonNullMessage() { final RingBufferLogEvent evt = new RingBufferLogEvent(); final String loggerName = null; final Marker marker = null; @@ -164,11 +162,11 @@ public void testGetMessageReturnsNonNullMessage() { location, new FixedPreciseClock(), new DummyNanoClock(1)); - assertNotNull(evt.getMessage()); + assertThat(evt.getMessage()).isNotNull(); } @Test - public void testGetMillisReturnsConstructorMillisForNormalMessage() { + void testGetMillisReturnsConstructorMillisForNormalMessage() { final RingBufferLogEvent evt = new RingBufferLogEvent(); final String loggerName = null; final Marker marker = null; @@ -195,12 +193,12 @@ public void testGetMillisReturnsConstructorMillisForNormalMessage() { location, new FixedPreciseClock(123, 456), new DummyNanoClock(1)); - assertEquals(123, evt.getTimeMillis()); - assertEquals(456, evt.getInstant().getNanoOfMillisecond()); + assertThat(evt.getTimeMillis()).isEqualTo(123); + assertThat(evt.getInstant().getNanoOfMillisecond()).isEqualTo(456); } @Test - public void testSerializationDeserialization() throws IOException, ClassNotFoundException { + void testSerializationDeserialization() throws IOException, ClassNotFoundException { final RingBufferLogEvent evt = new RingBufferLogEvent(); final String loggerName = "logger.name"; final Marker marker = null; @@ -235,24 +233,24 @@ public void testSerializationDeserialization() throws IOException, ClassNotFound final ObjectInputStream in = new FilteredObjectInputStream(new ByteArrayInputStream(baos.toByteArray())); final RingBufferLogEvent other = (RingBufferLogEvent) in.readObject(); - assertEquals(loggerName, other.getLoggerName()); - assertEquals(marker, other.getMarker()); - assertEquals(fqcn, other.getLoggerFqcn()); - assertEquals(level, other.getLevel()); - assertEquals(data, other.getMessage()); - assertNull("null after serialization", other.getThrown()); - assertEquals(new ThrowableProxy(t), other.getThrownProxy()); - assertEquals(evt.getContextData(), other.getContextData()); - assertEquals(contextStack, other.getContextStack()); - assertEquals(threadName, other.getThreadName()); - assertEquals(location, other.getSource()); - assertEquals(12345, other.getTimeMillis()); - assertEquals(678, other.getInstant().getNanoOfMillisecond()); + 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); } @SuppressWarnings("deprecation") @Test - public void testCreateMementoReturnsCopy() { + void testCreateMementoReturnsCopy() { final RingBufferLogEvent evt = new RingBufferLogEvent(); final String loggerName = "logger.name"; final Marker marker = MarkerManager.getMarker("marked man"); @@ -282,25 +280,25 @@ public void testCreateMementoReturnsCopy() { ((StringMap) evt.getContextData()).putValue("key", "value"); final LogEvent actual = evt.createMemento(); - assertEquals(evt.getLoggerName(), actual.getLoggerName()); - assertEquals(evt.getMarker(), actual.getMarker()); - assertEquals(evt.getLoggerFqcn(), actual.getLoggerFqcn()); - assertEquals(evt.getLevel(), actual.getLevel()); - assertEquals(evt.getMessage(), actual.getMessage()); - assertEquals(evt.getThrown(), actual.getThrown()); - assertEquals(evt.getContextMap(), actual.getContextMap()); - assertEquals(evt.getContextData(), actual.getContextData()); - assertEquals(evt.getContextStack(), actual.getContextStack()); - assertEquals(evt.getThreadName(), actual.getThreadName()); - assertEquals(evt.getTimeMillis(), actual.getTimeMillis()); - assertEquals( - evt.getInstant().getNanoOfMillisecond(), actual.getInstant().getNanoOfMillisecond()); - assertEquals(evt.getSource(), actual.getSource()); - assertEquals(evt.getThrownProxy(), actual.getThrownProxy()); + assertThat(actual.getLoggerName()).isEqualTo(evt.getLoggerName()); + assertThat(actual.getMarker()).isEqualTo(evt.getMarker()); + assertThat(actual.getLoggerFqcn()).isEqualTo(evt.getLoggerFqcn()); + assertThat(actual.getLevel()).isEqualTo(evt.getLevel()); + assertThat(actual.getMessage()).isEqualTo(evt.getMessage()); + assertThat(actual.getThrown()).isEqualTo(evt.getThrown()); + assertThat(actual.getContextMap()).isEqualTo(evt.getContextMap()); + assertThat(actual.getContextData()).isEqualTo(evt.getContextData()); + assertThat(actual.getContextStack()).isEqualTo(evt.getContextStack()); + assertThat(actual.getThreadName()).isEqualTo(evt.getThreadName()); + assertThat(actual.getTimeMillis()).isEqualTo(evt.getTimeMillis()); + assertThat(actual.getInstant().getNanoOfMillisecond()) + .isEqualTo(evt.getInstant().getNanoOfMillisecond()); + assertThat(actual.getSource()).isEqualTo(evt.getSource()); + assertThat(actual.getThrownProxy()).isEqualTo(evt.getThrownProxy()); } @Test - public void testCreateMementoRetainsParametersAndFormat() { + void testCreateMementoRetainsParametersAndFormat() { final RingBufferLogEvent evt = new RingBufferLogEvent(); // Initialize the event with parameters evt.swapParameters(new Object[10]); @@ -334,16 +332,16 @@ public void testCreateMementoRetainsParametersAndFormat() { ((StringMap) evt.getContextData()).putValue("key", "value"); final Message actual = evt.createMemento().getMessage(); - assertEquals("Hello {}!", actual.getFormat()); - assertArrayEquals(new String[] {"World"}, actual.getParameters()); - assertEquals("Hello World!", actual.getFormattedMessage()); + assertThat(actual.getFormat()).isEqualTo("Hello {}!"); + assertThat(actual.getParameters()).isEqualTo(new String[] {"World"}); + assertThat(actual.getFormattedMessage()).isEqualTo("Hello World!"); } finally { ReusableMessageFactory.release(message); } } @Test - public void testMementoReuse() { + void testMementoReuse() { final RingBufferLogEvent evt = new RingBufferLogEvent(); // Initialize the event with parameters evt.swapParameters(new Object[10]); @@ -378,25 +376,99 @@ public void testMementoReuse() { final Message memento1 = evt.memento(); final Message memento2 = evt.memento(); - assertThat(memento1, sameInstance(memento2)); + assertThat(memento1).isSameAs(memento2); } finally { ReusableMessageFactory.release(message); } } @Test - public void testMessageTextNeverThrowsNpe() { + void testMessageTextNeverThrowsNpe() { final RingBufferLogEvent evt = new RingBufferLogEvent(); - try { - evt.getFormattedMessage(); - } catch (final NullPointerException e) { - fail("the messageText field was not set"); - } + assertThatCode(evt::getFormattedMessage).doesNotThrowAnyException(); } @Test - public void testForEachParameterNothingSet() { + void testForEachParameterNothingSet() { final RingBufferLogEvent evt = new RingBufferLogEvent(); - evt.forEachParameter((parameter, parameterIndex, state) -> fail("Should not have been called"), null); + assertThatCode(() -> evt.forEachParameter( + (parameter, parameterIndex, state) -> fail("Should not have been called"), null)) + .doesNotThrowAnyException(); + } + + /** + * Reproduces #2234. + */ + @Test + void testGettersAndClear() { + + // Create mock fields + final long salt = (long) (Math.random() * 1_000L); + final AsyncLogger asyncLogger = mock(AsyncLogger.class); + final String loggerName = "LoggerName-" + salt; + final Marker marker = MarkerManager.getMarker("marker-" + salt); + final String fqcn = "a.b.c_" + salt; + final Level level = Level.TRACE; + final Message message = mock(Message.class); + final Throwable throwable = mock(Throwable.class); + final StringMap contextData = mock(StringMap.class); + final ContextStack contextStack = mock(ContextStack.class); + final String threadName = "threadName-" + salt; + final StackTraceElement location = new RuntimeException().getStackTrace()[0]; + + // Create the log event + final Clock clock = mock(Clock.class); + final NanoClock nanoClock = mock(NanoClock.class); + final RingBufferLogEvent event = new RingBufferLogEvent(); + event.setValues( + asyncLogger, + loggerName, + marker, + fqcn, + level, + message, + throwable, + contextData, + contextStack, + -1, + threadName, + -1, + location, + clock, + nanoClock); + + // Verify getters + assertThat(event.getLoggerName()).isSameAs(loggerName); + assertThat(event.getMarker()).isSameAs(marker); + assertThat(event.getLoggerFqcn()).isSameAs(fqcn); + assertThat(event.getLevel()).isSameAs(level); + assertThat(event.getMessage()).isSameAs(message); + assertThat(event.getThrowable()).isSameAs(throwable); + assertThat(event.getContextData()).isSameAs(contextData); + assertThat(event.getContextStack()).isSameAs(contextStack); + assertThat(event.getThreadName()).isSameAs(threadName); + assertThat(event.getSource()).isSameAs(location); + + // Verify clear + event.clear(); + assertThat(event.getLoggerName()).isNull(); + assertThat(event.getMarker()).isNull(); + assertThat(event.getLoggerFqcn()).isNull(); + assertThat(event.getLevel()).isEqualTo(Level.OFF); + verify(message).getFormattedMessage(); + assertThat(event.getMessage()) + .isNotSameAs(message) + .extracting(Message::getFormattedMessage, as(InstanceOfAssertFactories.STRING)) + .isEmpty(); + assertThat(event.getThrowable()).isNull(); + verify(contextData).isFrozen(); + verify(contextData).clear(); + assertThat(event.getContextData()).isSameAs(contextData); + assertThat(event.getContextStack()).isNull(); + assertThat(event.getThreadName()).isNull(); + assertThat(event.getSource()).isNull(); + + // Verify interaction exhaustion + verifyNoMoreInteractions(asyncLogger, message, throwable, contextData, contextStack); } } diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java index cf3259bce86..7c6e98e04e7 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java @@ -415,26 +415,23 @@ public long getNanoTime() { */ public void clear() { this.populated = false; - - this.asyncLogger = null; - this.loggerName = null; - this.marker = null; - this.fqcn = null; this.level = null; + this.threadName = null; + this.loggerName = null; this.message = null; this.messageFormat = null; + clearMessageTextAndParameters(); this.thrown = null; this.thrownProxy = null; - this.contextStack = null; + clearContextData(); + this.marker = null; + this.fqcn = null; this.location = null; - if (contextData != null) { - if (contextData.isFrozen()) { // came from CopyOnWrite thread context - contextData = null; - } else { - contextData.clear(); - } - } + this.contextStack = null; + this.asyncLogger = null; + } + private void clearMessageTextAndParameters() { // ensure that excessively long char[] arrays are not kept in memory forever if (Constants.ENABLE_THREADLOCALS) { StringBuilders.trimToMaxSize(messageText, Constants.MAX_REUSABLE_MESSAGE_SIZE); @@ -451,6 +448,16 @@ public void clear() { } } + private void clearContextData() { + if (contextData != null) { + if (contextData.isFrozen()) { // came from CopyOnWrite thread context + contextData = null; + } else { + contextData.clear(); + } + } + } + private void writeObject(final java.io.ObjectOutputStream out) throws IOException { getThrownProxy(); // initialize the ThrowableProxy before serializing out.defaultWriteObject(); diff --git a/src/changelog/.2.x.x/fix_RingBufferLogEvent_clear.xml b/src/changelog/.2.x.x/fix_RingBufferLogEvent_clear.xml new file mode 100644 index 00000000000..13b79f61fa3 --- /dev/null +++ b/src/changelog/.2.x.x/fix_RingBufferLogEvent_clear.xml @@ -0,0 +1,10 @@ + + + + + Fix forgotten `threadName` field in `RingBufferLogEvent#clear()` + +