Skip to content

Commit 0c5c21d

Browse files
vyvy
committed
Fix forgotten threadName field in RingBufferLogEvent#clear() (#2234, #2239)
1 parent 56c3848 commit 0c5c21d

File tree

2 files changed

+152
-70
lines changed

2 files changed

+152
-70
lines changed

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

Lines changed: 130 additions & 55 deletions
Original file line numberDiff line numberDiff line change
@@ -16,51 +16,52 @@
1616
*/
1717
package org.apache.logging.log4j.core.async;
1818

19-
import static org.hamcrest.CoreMatchers.sameInstance;
20-
import static org.hamcrest.MatcherAssert.assertThat;
21-
import static org.junit.jupiter.api.Assertions.assertArrayEquals;
22-
import static org.junit.jupiter.api.Assertions.assertEquals;
23-
import static org.junit.jupiter.api.Assertions.assertFalse;
24-
import static org.junit.jupiter.api.Assertions.assertNotNull;
25-
import static org.junit.jupiter.api.Assertions.assertNotSame;
26-
import static org.junit.jupiter.api.Assertions.assertTrue;
27-
import static org.junit.jupiter.api.Assertions.fail;
19+
import static org.assertj.core.api.Assertions.as;
20+
import static org.assertj.core.api.Assertions.assertThat;
21+
import static org.assertj.core.api.Assertions.assertThatCode;
22+
import static org.assertj.core.api.Assertions.fail;
23+
import static org.mockito.Mockito.mock;
24+
import static org.mockito.Mockito.verify;
25+
import static org.mockito.Mockito.verifyNoMoreInteractions;
2826

2927
import java.util.Arrays;
3028
import org.apache.logging.log4j.Level;
3129
import org.apache.logging.log4j.Marker;
3230
import org.apache.logging.log4j.MarkerManager;
3331
import org.apache.logging.log4j.ThreadContext.ContextStack;
3432
import org.apache.logging.log4j.core.LogEvent;
33+
import org.apache.logging.log4j.core.time.Clock;
34+
import org.apache.logging.log4j.core.time.NanoClock;
3535
import org.apache.logging.log4j.core.time.internal.DummyNanoClock;
3636
import org.apache.logging.log4j.core.time.internal.FixedPreciseClock;
3737
import org.apache.logging.log4j.message.Message;
3838
import org.apache.logging.log4j.message.ReusableMessageFactory;
3939
import org.apache.logging.log4j.message.SimpleMessage;
4040
import org.apache.logging.log4j.spi.MutableThreadContextStack;
41+
import org.apache.logging.log4j.util.StringMap;
42+
import org.assertj.core.api.InstanceOfAssertFactories;
4143
import org.junit.jupiter.api.Tag;
4244
import org.junit.jupiter.api.Test;
4345

4446
/**
4547
* Tests the RingBufferLogEvent class.
4648
*/
4749
@Tag("async")
48-
public class RingBufferLogEventTest {
50+
class RingBufferLogEventTest {
4951

5052
@Test
51-
public void testToImmutable() {
53+
void testToImmutable() {
5254
final LogEvent logEvent = new RingBufferLogEvent();
53-
assertNotSame(logEvent, logEvent.toImmutable());
55+
assertThat(logEvent).isNotSameAs(logEvent.toImmutable());
5456
}
5557

5658
/**
57-
* @see <a href="https://issues.apache.org/jira/browse/LOG4J2-2816">LOG4J2-2816</a>
59+
* Reproduces <a href="https://issues.apache.org/jira/browse/LOG4J2-2816">LOG4J2-2816</a>.
5860
*/
5961
@Test
60-
public void testIsPopulated() {
62+
void testIsPopulated() {
6163
final RingBufferLogEvent evt = new RingBufferLogEvent();
62-
63-
assertFalse(evt.isPopulated());
64+
assertThat(evt.isPopulated()).isFalse();
6465

6566
final String loggerName = null;
6667
final Marker marker = null;
@@ -88,15 +89,15 @@ public void testIsPopulated() {
8889
new FixedPreciseClock(),
8990
new DummyNanoClock(1));
9091

91-
assertTrue(evt.isPopulated());
92+
assertThat(evt.isPopulated()).isTrue();
9293

9394
evt.clear();
9495

95-
assertFalse(evt.isPopulated());
96+
assertThat(evt.isPopulated()).isFalse();
9697
}
9798

9899
@Test
99-
public void testGetLevelReturnsOffIfNullLevelSet() {
100+
void testGetLevelReturnsOffIfNullLevelSet() {
100101
final RingBufferLogEvent evt = new RingBufferLogEvent();
101102
final String loggerName = null;
102103
final Marker marker = null;
@@ -123,11 +124,11 @@ public void testGetLevelReturnsOffIfNullLevelSet() {
123124
location,
124125
new FixedPreciseClock(),
125126
new DummyNanoClock(1));
126-
assertEquals(Level.OFF, evt.getLevel());
127+
assertThat(evt.getLevel()).isEqualTo(Level.OFF);
127128
}
128129

129130
@Test
130-
public void testGetMessageReturnsNonNullMessage() {
131+
void testGetMessageReturnsNonNullMessage() {
131132
final RingBufferLogEvent evt = new RingBufferLogEvent();
132133
final String loggerName = null;
133134
final Marker marker = null;
@@ -154,11 +155,11 @@ public void testGetMessageReturnsNonNullMessage() {
154155
location,
155156
new FixedPreciseClock(),
156157
new DummyNanoClock(1));
157-
assertNotNull(evt.getMessage());
158+
assertThat(evt.getMessage()).isNotNull();
158159
}
159160

160161
@Test
161-
public void testGetMillisReturnsConstructorMillisForNormalMessage() {
162+
void testGetMillisReturnsConstructorMillisForNormalMessage() {
162163
final RingBufferLogEvent evt = new RingBufferLogEvent();
163164
final String loggerName = null;
164165
final Marker marker = null;
@@ -185,12 +186,12 @@ public void testGetMillisReturnsConstructorMillisForNormalMessage() {
185186
location,
186187
new FixedPreciseClock(123, 456),
187188
new DummyNanoClock(1));
188-
assertEquals(123, evt.getTimeMillis());
189-
assertEquals(456, evt.getInstant().getNanoOfMillisecond());
189+
assertThat(evt.getTimeMillis()).isEqualTo(123);
190+
assertThat(evt.getInstant().getNanoOfMillisecond()).isEqualTo(456);
190191
}
191192

192193
@Test
193-
public void testCreateMementoReturnsCopy() {
194+
void testCreateMementoReturnsCopy() {
194195
final RingBufferLogEvent evt = new RingBufferLogEvent();
195196
final String loggerName = "logger.name";
196197
final Marker marker = MarkerManager.getMarker("marked man");
@@ -220,24 +221,24 @@ public void testCreateMementoReturnsCopy() {
220221
evt.getContextData().putValue("key", "value");
221222

222223
final LogEvent actual = evt.toMemento();
223-
assertEquals(evt.getLoggerName(), actual.getLoggerName());
224-
assertEquals(evt.getMarker(), actual.getMarker());
225-
assertEquals(evt.getLoggerFqcn(), actual.getLoggerFqcn());
226-
assertEquals(evt.getLevel(), actual.getLevel());
227-
assertEquals(evt.getMessage(), actual.getMessage());
228-
assertEquals(evt.getThrown(), actual.getThrown());
229-
assertEquals(evt.getContextData(), actual.getContextData());
230-
assertEquals(evt.getContextStack(), actual.getContextStack());
231-
assertEquals(evt.getThreadName(), actual.getThreadName());
232-
assertEquals(evt.getTimeMillis(), actual.getTimeMillis());
233-
assertEquals(
234-
evt.getInstant().getNanoOfMillisecond(), actual.getInstant().getNanoOfMillisecond());
235-
assertEquals(evt.getSource(), actual.getSource());
236-
assertEquals(evt.getThrownProxy(), actual.getThrownProxy());
224+
assertThat(actual.getLoggerName()).isEqualTo(evt.getLoggerName());
225+
assertThat(actual.getMarker()).isEqualTo(evt.getMarker());
226+
assertThat(actual.getLoggerFqcn()).isEqualTo(evt.getLoggerFqcn());
227+
assertThat(actual.getLevel()).isEqualTo(evt.getLevel());
228+
assertThat(actual.getMessage()).isEqualTo(evt.getMessage());
229+
assertThat(actual.getThrown()).isEqualTo(evt.getThrown());
230+
assertThat(actual.getContextData()).isEqualTo(evt.getContextData());
231+
assertThat(actual.getContextStack()).isEqualTo(evt.getContextStack());
232+
assertThat(actual.getThreadName()).isEqualTo(evt.getThreadName());
233+
assertThat(actual.getTimeMillis()).isEqualTo(evt.getTimeMillis());
234+
assertThat(actual.getInstant().getNanoOfMillisecond())
235+
.isEqualTo(evt.getInstant().getNanoOfMillisecond());
236+
assertThat(actual.getSource()).isEqualTo(evt.getSource());
237+
assertThat(actual.getThrownProxy()).isEqualTo(evt.getThrownProxy());
237238
}
238239

239240
@Test
240-
public void testCreateMementoRetainsParametersAndFormat() {
241+
void testCreateMementoRetainsParametersAndFormat() {
241242
final RingBufferLogEvent evt = new RingBufferLogEvent();
242243
// Initialize the event with parameters
243244
evt.swapParameters(new Object[10]);
@@ -271,16 +272,16 @@ public void testCreateMementoRetainsParametersAndFormat() {
271272
evt.getContextData().putValue("key", "value");
272273

273274
final Message actual = evt.toMemento().getMessage();
274-
assertEquals("Hello {}!", actual.getFormat());
275-
assertArrayEquals(new String[] {"World"}, actual.getParameters());
276-
assertEquals("Hello World!", actual.getFormattedMessage());
275+
assertThat(actual.getFormat()).isEqualTo("Hello {}!");
276+
assertThat(actual.getParameters()).isEqualTo(new String[] {"World"});
277+
assertThat(actual.getFormattedMessage()).isEqualTo("Hello World!");
277278
} finally {
278-
factory.recycle(message);
279+
ReusableMessageFactory.release(message);
279280
}
280281
}
281282

282283
@Test
283-
public void testMementoReuse() {
284+
void testMementoReuse() {
284285
final RingBufferLogEvent evt = new RingBufferLogEvent();
285286
// Initialize the event with parameters
286287
evt.swapParameters(new Object[10]);
@@ -315,25 +316,99 @@ public void testMementoReuse() {
315316

316317
final Message memento1 = evt.memento();
317318
final Message memento2 = evt.memento();
318-
assertThat(memento1, sameInstance(memento2));
319+
assertThat(memento1).isSameAs(memento2);
319320
} finally {
320321
factory.recycle(message);
321322
}
322323
}
323324

324325
@Test
325-
public void testMessageTextNeverThrowsNpe() {
326+
void testMessageTextNeverThrowsNpe() {
326327
final RingBufferLogEvent evt = new RingBufferLogEvent();
327-
try {
328-
evt.getFormattedMessage();
329-
} catch (final NullPointerException e) {
330-
fail("the messageText field was not set");
331-
}
328+
assertThatCode(evt::getFormattedMessage).doesNotThrowAnyException();
332329
}
333330

334331
@Test
335-
public void testForEachParameterNothingSet() {
332+
void testForEachParameterNothingSet() {
336333
final RingBufferLogEvent evt = new RingBufferLogEvent();
337-
evt.forEachParameter((parameter, parameterIndex, state) -> fail("Should not have been called"), null);
334+
assertThatCode(() -> evt.forEachParameter(
335+
(parameter, parameterIndex, state) -> fail("Should not have been called"), null))
336+
.doesNotThrowAnyException();
337+
}
338+
339+
/**
340+
* Reproduces <a href="https://github.com/apache/logging-log4j2/issues/2234">#2234</a>.
341+
*/
342+
@Test
343+
void testGettersAndClear() {
344+
345+
// Create mock fields
346+
final long salt = (long) (Math.random() * 1_000L);
347+
final AsyncLogger asyncLogger = mock(AsyncLogger.class);
348+
final String loggerName = "LoggerName-" + salt;
349+
final Marker marker = MarkerManager.getMarker("marker-" + salt);
350+
final String fqcn = "a.b.c_" + salt;
351+
final Level level = Level.TRACE;
352+
final Message message = mock(Message.class);
353+
final Throwable throwable = mock(Throwable.class);
354+
final StringMap contextData = mock(StringMap.class);
355+
final ContextStack contextStack = mock(ContextStack.class);
356+
final String threadName = "threadName-" + salt;
357+
final StackTraceElement location = new RuntimeException().getStackTrace()[0];
358+
359+
// Create the log event
360+
final Clock clock = mock(Clock.class);
361+
final NanoClock nanoClock = mock(NanoClock.class);
362+
final RingBufferLogEvent event = new RingBufferLogEvent();
363+
event.setValues(
364+
asyncLogger,
365+
loggerName,
366+
marker,
367+
fqcn,
368+
level,
369+
message,
370+
throwable,
371+
contextData,
372+
contextStack,
373+
-1,
374+
threadName,
375+
-1,
376+
location,
377+
clock,
378+
nanoClock);
379+
380+
// Verify getters
381+
assertThat(event.getLoggerName()).isSameAs(loggerName);
382+
assertThat(event.getMarker()).isSameAs(marker);
383+
assertThat(event.getLoggerFqcn()).isSameAs(fqcn);
384+
assertThat(event.getLevel()).isSameAs(level);
385+
assertThat(event.getMessage()).isSameAs(message);
386+
assertThat(event.getThrowable()).isSameAs(throwable);
387+
assertThat(event.getContextData()).isSameAs(contextData);
388+
assertThat(event.getContextStack()).isSameAs(contextStack);
389+
assertThat(event.getThreadName()).isSameAs(threadName);
390+
assertThat(event.getSource()).isSameAs(location);
391+
392+
// Verify clear
393+
event.clear();
394+
assertThat(event.getLoggerName()).isNull();
395+
assertThat(event.getMarker()).isNull();
396+
assertThat(event.getLoggerFqcn()).isNull();
397+
assertThat(event.getLevel()).isEqualTo(Level.OFF);
398+
verify(message).getFormattedMessage();
399+
assertThat(event.getMessage())
400+
.isNotSameAs(message)
401+
.extracting(Message::getFormattedMessage, as(InstanceOfAssertFactories.STRING))
402+
.isEmpty();
403+
assertThat(event.getThrowable()).isNull();
404+
verify(contextData).isFrozen();
405+
verify(contextData).clear();
406+
assertThat(event.getContextData()).isSameAs(contextData);
407+
assertThat(event.getContextStack()).isNull();
408+
assertThat(event.getThreadName()).isNull();
409+
assertThat(event.getSource()).isNull();
410+
411+
// Verify interaction exhaustion
412+
verifyNoMoreInteractions(asyncLogger, message, throwable, contextData, contextStack);
338413
}
339414
}

‎log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java‎

Lines changed: 22 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -475,26 +475,23 @@ public void setNanoTime(final long nanoTime) {
475475
@Override
476476
public void clear() {
477477
this.populated = false;
478-
479-
this.asyncLogger = null;
480-
this.loggerName = null;
481-
this.marker = null;
482-
this.fqcn = null;
483478
this.level = null;
484-
this.message = null;
485-
this.messageFormat = null;
479+
this.threadName = null;
480+
this.loggerName = null;
481+
clearMessage();
486482
this.thrown = null;
487483
this.thrownProxy = null;
488-
this.contextStack = null;
484+
clearContextData();
485+
this.marker = null;
486+
this.fqcn = null;
489487
this.location = null;
490-
if (contextData != null) {
491-
if (contextData.isFrozen()) { // came from CopyOnWrite thread context
492-
contextData = null;
493-
} else {
494-
contextData.clear();
495-
}
496-
}
488+
this.contextStack = null;
489+
this.asyncLogger = null;
490+
}
497491

492+
private void clearMessage() {
493+
message = null;
494+
messageFormat = null;
498495
// ensure that excessively long char[] arrays are not kept in memory forever
499496
StringBuilders.trimToMaxSize(messageText, Constants.MAX_REUSABLE_MESSAGE_SIZE);
500497

@@ -503,6 +500,16 @@ public void clear() {
503500
}
504501
}
505502

503+
private void clearContextData() {
504+
if (contextData != null) {
505+
if (contextData.isFrozen()) { // came from CopyOnWrite thread context
506+
contextData = null;
507+
} else {
508+
contextData.clear();
509+
}
510+
}
511+
}
512+
506513
/**
507514
* Initializes the specified {@code Log4jLogEvent.Builder} from this {@code RingBufferLogEvent}.
508515
* @param builder the builder whose fields to populate

0 commit comments

Comments
 (0)