Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Consolidate stack trace rendering in Pattern Layout #3047

Merged
merged 3 commits into from
Oct 2, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -27,7 +27,6 @@
import org.apache.logging.log4j.core.impl.ContextDataFactory;
import org.apache.logging.log4j.core.impl.Log4jLogEvent;
import org.apache.logging.log4j.core.impl.MementoMessage;
import org.apache.logging.log4j.core.impl.ThrowableProxy;
import org.apache.logging.log4j.core.time.Clock;
import org.apache.logging.log4j.core.time.Instant;
import org.apache.logging.log4j.core.time.MutableInstant;
Expand Down Expand Up @@ -82,7 +81,6 @@ public RingBufferLogEvent newInstance() {
private StringBuilder messageText;
private Object[] parameters;
private Throwable thrown;
private ThrowableProxy thrownProxy;
private StringMap contextData = ContextDataFactory.createContextData();
private Marker marker;
private String fqcn;
Expand Down Expand Up @@ -116,7 +114,6 @@ public void setValues(
initTime(clock);
this.nanoTime = nanoClock.nanoTime();
this.thrown = aThrowable;
this.thrownProxy = null;
this.marker = aMarker;
this.fqcn = theFqcn;
this.location = aLocation;
Expand Down Expand Up @@ -354,12 +351,6 @@ public CharSequence subSequence(final int start, final int end) {

@Override
public Throwable getThrown() {
// after deserialization, thrown is null but thrownProxy may be non-null
if (thrown == null) {
if (thrownProxy != null) {
thrown = thrownProxy.getThrowable();
}
}
return thrown;
}

Expand All @@ -368,17 +359,6 @@ public void setThrown(final Throwable thrown) {
this.thrown = thrown;
}

@Override
public ThrowableProxy getThrownProxy() {
// lazily instantiate the (expensive) ThrowableProxy
if (thrownProxy == null) {
if (thrown != null) {
thrownProxy = new ThrowableProxy(thrown);
}
}
return this.thrownProxy;
}

@Override
public StringMap getContextData() {
return contextData;
Expand Down Expand Up @@ -487,7 +467,6 @@ public void clear() {
this.loggerName = null;
clearMessage();
this.thrown = null;
this.thrownProxy = null;
clearContextData();
this.marker = null;
this.fqcn = null;
Expand Down Expand Up @@ -546,8 +525,7 @@ public void initializeBuilder(final Log4jLogEvent.Builder builder) {
.setThreadId(threadId) //
.setThreadName(threadName) //
.setThreadPriority(threadPriority) //
.setThrown(getThrown()) // may deserialize from thrownProxy
.setThrownProxy(thrownProxy) // avoid unnecessarily creating thrownProxy
.setThrown(getThrown()) //
.setInstant(instant) //
;
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -235,7 +235,6 @@ void testCreateMementoReturnsCopy() {
assertThat(actual.getInstant().getNanoOfMillisecond())
.isEqualTo(evt.getInstant().getNanoOfMillisecond());
assertThat(actual.getSource()).isEqualTo(evt.getSource());
assertThat(actual.getThrownProxy()).isEqualTo(evt.getThrownProxy());
}

@Test
Expand Down
6 changes: 6 additions & 0 deletions log4j-core-test/pom.xml
Original file line number Diff line number Diff line change
Expand Up @@ -65,6 +65,12 @@

<dependencies>

<dependency>
<groupId>org.jspecify</groupId>
<artifactId>jspecify</artifactId>
<scope>provided</scope>
</dependency>

<!-- Used for OSGi bundle support -->
<dependency>
<groupId>org.osgi</groupId>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -28,7 +28,6 @@
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.impl.ContextDataFactory;
import org.apache.logging.log4j.core.impl.Log4jLogEvent;
import org.apache.logging.log4j.core.impl.ThrowableProxy;
import org.apache.logging.log4j.message.SimpleMessage;
import org.apache.logging.log4j.spi.DefaultThreadContextStack;
import org.apache.logging.log4j.util.StringMap;
Expand Down Expand Up @@ -56,7 +55,6 @@ public static Log4jLogEvent createLogEvent() {
final IOException ioException = new IOException("testIOEx", cause);
ioException.addSuppressed(new IndexOutOfBoundsException("I am suppressed exception 1"));
ioException.addSuppressed(new IndexOutOfBoundsException("I am suppressed exception 2"));
final ThrowableProxy throwableProxy = new ThrowableProxy(ioException);
final StringMap contextData = ContextDataFactory.createContextData();
contextData.putValue("MDC.A", "A_Value");
contextData.putValue("MDC.B", "B_Value");
Expand All @@ -71,7 +69,6 @@ public static Log4jLogEvent createLogEvent() {
.setLevel(Level.DEBUG) //
.setMessage(new SimpleMessage("Msg")) //
.setThrown(ioException) //
.setThrownProxy(throwableProxy) //
.setContextData(contextData) //
.setContextStack(contextStack) //
.setThreadName("MyThreadName") //
Expand Down Expand Up @@ -103,14 +100,11 @@ public static void assertEqualLogEvents(
assertEquals(expected.getThreadName(), actual.getThreadName());
assertNotNull("original should have an exception", expected.getThrown());
assertNull("exception should not be serialized", actual.getThrown());
if (includeStacktrace) { // TODO should compare the rest of the ThrowableProxy
assertEquals(expected.getThrownProxy(), actual.getThrownProxy());
}
assertEquals(expected.isEndOfBatch(), actual.isEndOfBatch());
assertEquals(expected.isIncludeLocation(), actual.isIncludeLocation());

// original: non-null thrown & null thrownProxy
// deserialized: null thrown & non-null thrownProxy
// original: non-null thrown
// deserialized: null thrown
assertNotEquals(expected.hashCode(), actual.hashCode());
assertNotEquals(expected, actual);
}
Expand Down
155 changes: 155 additions & 0 deletions log4j-core-test/src/test/java/foo/TestFriendlyException.java
Original file line number Diff line number Diff line change
@@ -0,0 +1,155 @@
/*
* 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 foo;

import static org.assertj.core.api.Assertions.assertThat;

import java.net.Socket;
import java.util.Arrays;
import java.util.stream.Stream;
import org.apache.logging.log4j.util.Constants;

/**
* A testing friendly exception featuring
* <ul>
* <li>Distinct localized message</li>
* <li>Non-Log4j package origin<sup>1</sup></li>
* <li>Sufficient causal chain depth</li>
* <li>Cyclic causal chain</li>
* <li>Suppressed exceptions</li>
* <li>Clutter-free stack trace (i.e., elements from JUnit, JDK, etc.)</li>
* <li>Stack trace elements from named modules<sup>2</sup></li>
* </ul>
* <p>
* <sup>1</sup> Helps with observing stack trace manipulation effects of Log4j.
* </p>
* <p>
* <sup>2</sup> Helps with testing module name serialization.
* </p>
*/
public final class TestFriendlyException extends RuntimeException {

static {
// Ensure the distinct packaging
assertThat(TestFriendlyException.class.getPackage().getName()).doesNotStartWith("org.apache");
}

public static final StackTraceElement NAMED_MODULE_STACK_TRACE_ELEMENT = namedModuleStackTraceElement();

@SuppressWarnings("resource")
private static StackTraceElement namedModuleStackTraceElement() {
try {
new Socket("0.0.0.0", -1);
} catch (final Exception error) {
final StackTraceElement[] stackTraceElements = error.getStackTrace();
final String socketClassName = Socket.class.getCanonicalName();
for (final StackTraceElement stackTraceElement : stackTraceElements) {
if (stackTraceElement.getClassName().equals(socketClassName)) {
if (Constants.JAVA_MAJOR_VERSION > 8) {
final String stackTraceElementString = stackTraceElement.toString();
assertThat(stackTraceElementString).startsWith("java.base/");
}
return stackTraceElement;
}
}
}
throw new IllegalStateException("should not have reached here");
}

private static final String[] EXCLUDED_CLASS_NAME_PREFIXES = {
"java.lang", "jdk.internal", "org.junit", "sun.reflect"
};

public static final TestFriendlyException INSTANCE = create("r", 0, 2, new boolean[] {false}, new boolean[] {true});

private static TestFriendlyException create(
final String name,
final int depth,
final int maxDepth,
final boolean[] circular,
final boolean[] namedModuleAllowed) {
final TestFriendlyException error = new TestFriendlyException(name, namedModuleAllowed);
if (depth < maxDepth) {
final TestFriendlyException cause = create(name + "_c", depth + 1, maxDepth, circular, namedModuleAllowed);
error.initCause(cause);
final TestFriendlyException suppressed =
create(name + "_s", depth + 1, maxDepth, circular, namedModuleAllowed);
error.addSuppressed(suppressed);
final boolean circularAllowed = depth + 1 == maxDepth && !circular[0];
if (circularAllowed) {
cause.initCause(error);
suppressed.initCause(error);
circular[0] = true;
}
}
return error;
}

private TestFriendlyException(final String message, final boolean[] namedModuleAllowed) {
super(message);
removeExcludedStackTraceElements(namedModuleAllowed);
}

private void removeExcludedStackTraceElements(final boolean[] namedModuleAllowed) {
final StackTraceElement[] oldStackTrace = getStackTrace();
final boolean[] seenExcludedStackTraceElement = {false};
final StackTraceElement[] newStackTrace = Arrays.stream(oldStackTrace)
.flatMap(stackTraceElement ->
mapStackTraceElement(stackTraceElement, namedModuleAllowed, seenExcludedStackTraceElement))
.toArray(StackTraceElement[]::new);
setStackTrace(newStackTrace);
}

private static Stream<StackTraceElement> mapStackTraceElement(
final StackTraceElement stackTraceElement,
final boolean[] namedModuleAllowed,
final boolean[] seenExcludedStackTraceElement) {
final Stream<StackTraceElement> filteredStackTraceElement =
filterStackTraceElement(stackTraceElement, seenExcludedStackTraceElement);
final Stream<StackTraceElement> javaBaseIncludedStackTraceElement =
namedModuleIncludedStackTraceElement(namedModuleAllowed);
return Stream.concat(javaBaseIncludedStackTraceElement, filteredStackTraceElement);
}

private static Stream<StackTraceElement> filterStackTraceElement(
final StackTraceElement stackTraceElement, final boolean[] seenExcludedStackTraceElement) {
if (seenExcludedStackTraceElement[0]) {
return Stream.empty();
}
final String className = stackTraceElement.getClassName();
for (final String excludedClassNamePrefix : EXCLUDED_CLASS_NAME_PREFIXES) {
if (className.startsWith(excludedClassNamePrefix)) {
seenExcludedStackTraceElement[0] = true;
return Stream.empty();
}
}
return Stream.of(stackTraceElement);
}

private static Stream<StackTraceElement> namedModuleIncludedStackTraceElement(final boolean[] namedModuleAllowed) {
if (!namedModuleAllowed[0]) {
return Stream.of();
}
namedModuleAllowed[0] = false;
return Stream.of(NAMED_MODULE_STACK_TRACE_ELEMENT);
}

@Override
public String getLocalizedMessage() {
return getMessage() + " [localized]";
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@

import static org.hamcrest.MatcherAssert.assertThat;
import static org.hamcrest.Matchers.containsString;
import static org.hamcrest.Matchers.is;
import static org.junit.jupiter.api.Assertions.assertNull;
import static org.junit.jupiter.api.Assertions.assertTrue;

Expand Down Expand Up @@ -61,15 +62,20 @@ public void testParametersAreNotLeaked() throws Exception {
final String line1 = reader.readLine();
final String line2 = reader.readLine();
final String line3 = reader.readLine();
// line4 is empty line because of the line separator after throwable pattern
final String line4 = reader.readLine();
final String line5 = reader.readLine();
final String line6 = reader.readLine();
final String line7 = reader.readLine();
reader.close();
file.delete();
assertThat(line1, containsString("Message with parameter paramValue"));
assertThat(line2, containsString("paramValue"));
assertThat(line3, containsString("paramValue"));
assertThat(line4, containsString("paramValue"));
assertNull(line5, "Expected only three lines");
assertThat(line4, is(""));
assertThat(line5, containsString("paramValue"));
assertThat(line6, is(""));
assertNull(line7, "Expected only six lines");
try (final GarbageCollectionHelper gcHelper = new GarbageCollectionHelper()) {
gcHelper.run();
assertTrue(latch.await(30, TimeUnit.SECONDS), "Parameter should have been garbage collected");
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,6 @@
import static org.apache.logging.log4j.core.test.hamcrest.MapMatchers.hasSize;
import static org.hamcrest.MatcherAssert.assertThat;
import static org.hamcrest.Matchers.hasEntry;
import static org.junit.jupiter.api.Assertions.assertArrayEquals;
import static org.junit.jupiter.api.Assertions.assertEquals;

import java.util.ArrayList;
Expand Down Expand Up @@ -170,10 +169,7 @@ private void compareLogEvents(final LogEvent orig, final LogEvent changed) {
assertEquals(orig.getMarker(), changed.getMarker(), "Marker changed");
assertEquals(orig.getLoggerFqcn(), changed.getLoggerFqcn(), "FQCN changed");
assertEquals(orig.getLevel(), changed.getLevel(), "Level changed");
assertArrayEquals(
orig.getThrown() == null ? null : orig.getThrownProxy().getExtendedStackTrace(),
changed.getThrown() == null ? null : changed.getThrownProxy().getExtendedStackTrace(),
"Throwable changed");
assertEquals(orig.getThrown(), changed.getThrown(), "Throwable changed");
assertEquals(orig.getContextData(), changed.getContextData(), "ContextData changed");
assertEquals(orig.getContextStack(), changed.getContextStack(), "ContextStack changed");
assertEquals(orig.getThreadName(), changed.getThreadName(), "ThreadName changed");
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -50,8 +50,8 @@ public class RollingAppenderOnStartupTest {

@BeforeAll
static void setUp() throws IOException {
final Path target =
Files.copy(SOURCE.resolve(FILENAME), loggingPath.resolve(FILENAME), StandardCopyOption.COPY_ATTRIBUTES);
final Path target = Files.copy(
SOURCE.resolve(FILENAME), loggingPath.resolve(FILENAME), StandardCopyOption.REPLACE_EXISTING);
final FileTime newTime = FileTime.from(Instant.now().minus(1, ChronoUnit.DAYS));
final BasicFileAttributeView attrs = Files.getFileAttributeView(target, BasicFileAttributeView.class);
attrs.setTimes(newTime, newTime, newTime);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -76,7 +76,6 @@ public void testToImmutable() {

@Test
public void testInitFromCopiesAllFields() {
// private ThrowableProxy thrownProxy;
final Log4jLogEvent source = Log4jLogEvent.newBuilder() //
.setContextData(CONTEXT_DATA) //
.setContextStack(STACK) //
Expand Down Expand Up @@ -112,7 +111,6 @@ public void testInitFromCopiesAllFields() {
assertEquals(source.getThreadName(), mutable.getThreadName(), "tname");
assertEquals(source.getThreadPriority(), mutable.getThreadPriority(), "tpriority");
assertEquals(source.getThrown(), mutable.getThrown(), "throwns");
assertEquals(source.getThrownProxy(), mutable.getThrownProxy(), "proxy");
assertEquals(source.getTimeMillis(), mutable.getTimeMillis(), "millis");
}

Expand Down Expand Up @@ -216,7 +214,6 @@ public void testClear() {
assertEquals(0, mutable.getTimeMillis(), "timeMs");

assertNull(mutable.getSource(), "source");
assertNull(mutable.getThrownProxy(), "thrownProxy");

mutable.setContextData(CONTEXT_DATA);
mutable.setContextStack(STACK);
Expand Down Expand Up @@ -250,7 +247,6 @@ public void testClear() {
assertNotEquals(0, mutable.getTimeMillis(), "timeMs");

assertNotNull(mutable.getSource(), "source");
assertNotNull(mutable.getThrownProxy(), "thrownProxy");

mutable.clear();
assertEquals(0, mutable.getContextData().size(), "context map");
Expand All @@ -263,7 +259,6 @@ public void testClear() {
assertNull(mutable.getThrown(), "thrwn");

assertNull(mutable.getSource(), "source");
assertNull(mutable.getThrownProxy(), "thrownProxy");

// primitive fields are NOT reset:
assertTrue(mutable.isEndOfBatch(), "end of batch");
Expand Down
Loading