%xThrowable{depth} does not work

[garydgregory]

Description

The pattern %xThrowable{depth} does not work, for example, %xThrowable{2} and %xThrowable{99} both print the same stack trace, which is also the default stack trace without the depth taken into account.

Configuration

Version: 2.24.1

Microsoft Windows [Version 10.0.19045.5011]

openjdk version "17.0.12" 2024-07-16
OpenJDK Runtime Environment Temurin-17.0.12+7 (build 17.0.12+7)
OpenJDK 64-Bit Server VM Temurin-17.0.12+7 (build 17.0.12+7, mixed mode, sharing)

Apache Maven 3.9.9 (8e8579a9e76f7d015ee5ec7bfcdc97d260186937)
Maven home: C:\java\apache-maven-3.9.9
Java version: 17.0.12, vendor: Eclipse Adoptium, runtime: C:\Program Files\Eclipse Adoptium\jdk-17.0.12.7-hotspot
Default locale: en_US, platform encoding: Cp1252
OS name: "windows 10", version: "10.0", arch: "amd64", family: "windows"

Docker version 27.3.1, build ce12230

Logs

2024-10-30T09:48:38,726-0400 WARN  [main][test] msg
java.lang.IllegalArgumentException: parent
	at test.LoggingTest.test(LoggingTest.java:10) ~[test-classes/:?]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.base/java.lang.reflect.Method.invoke(Method.java:569) ~[?:?]
	at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:767) ~[junit-platform-commons-1.11.3.jar:1.11.3]
	at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60) ~[junit-jupiter-engine-5.11.3.jar:5.11.3]
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131) ~[junit-jupiter-engine-5.11.3.jar:5.11.3]
	at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:156) ~[junit-jupiter-engine-5.11.3.jar:5.11.3]
	at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:147) ~[junit-jupiter-engine-5.11.3.jar:5.11.3]
	at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:86) ~[junit-jupiter-engine-5.11.3.jar:5.11.3]
	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103) ~[junit-jupiter-engine-5.11.3.jar:5.11.3]
	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93) ~[junit-jupiter-engine-5.11.3.jar:5.11.3]
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106) ~[junit-jupiter-engine-5.11.3.jar:5.11.3]
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64) ~[junit-jupiter-engine-5.11.3.jar:5.11.3]
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45) ~[junit-jupiter-engine-5.11.3.jar:5.11.3]
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37) ~[junit-jupiter-engine-5.11.3.jar:5.11.3]
	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:92) ~[junit-jupiter-engine-5.11.3.jar:5.11.3]
	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:86) ~[junit-jupiter-engine-5.11.3.jar:5.11.3]
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$8(TestMethodTestDescriptor.java:217) ~[junit-jupiter-engine-5.11.3.jar:5.11.3]
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:213) ~[junit-jupiter-engine-5.11.3.jar:5.11.3]
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:138) ~[junit-jupiter-engine-5.11.3.jar:5.11.3]
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:68) ~[junit-jupiter-engine-5.11.3.jar:5.11.3]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:156) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:146) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:144) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:143) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:100) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511) ~[?:?]
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:160) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:146) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:144) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:143) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:100) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511) ~[?:?]
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:160) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:146) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:144) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:143) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:100) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:54) ~[junit-platform-engine-1.11.3.jar:1.11.3]
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:198) ~[junit-platform-launcher-1.11.3.jar:1.11.3]
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:169) ~[junit-platform-launcher-1.11.3.jar:1.11.3]
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:93) ~[junit-platform-launcher-1.11.3.jar:1.11.3]
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:58) ~[junit-platform-launcher-1.11.3.jar:1.11.3]
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:141) [junit-platform-launcher-1.11.3.jar:1.11.3]
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:57) [junit-platform-launcher-1.11.3.jar:1.11.3]
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:103) [junit-platform-launcher-1.11.3.jar:1.11.3]
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:94) [junit-platform-launcher-1.11.3.jar:1.11.3]
	at org.junit.platform.launcher.core.DelegatingLauncher.execute(DelegatingLauncher.java:52) [junit-platform-launcher-1.11.3.jar:1.11.3]
	at org.junit.platform.launcher.core.SessionPerRequestLauncher.execute(SessionPerRequestLauncher.java:70) [junit-platform-launcher-1.11.3.jar:1.11.3]
	at org.eclipse.jdt.internal.junit5.runner.JUnit5TestReference.run(JUnit5TestReference.java:100) [.cp/:?]
	at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:40) [.cp/:?]
	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:530) [.cp/:?]
	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:758) [.cp/:?]
	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:453) [.cp/:?]
	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:211) [.cp/:?]
Caused by: java.lang.IllegalArgumentException: child
	... 71 more

Reproduction

package test;

import org.apache.logging.log4j.LogManager;
import org.junit.jupiter.api.Test;

public class LoggingTest {

    @Test
    public void test() {
        LogManager.getLogger("test").warn("msg", new IllegalArgumentException("parent", new IllegalArgumentException("child").fillInStackTrace()).fillInStackTrace());
    }
}

Config:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="ERROR" monitorInterval="5">
  <Appenders>
    <Console name="Console" target="SYSTEM_OUT">
      <!-- For a color log in the Eclipse console: -->
      <!-- - Install http://www.mihai-nita.net/eclipse -->
      <!-- - Use noConsoleNoAnsi="false" -->
      <PatternLayout noConsoleNoAnsi="false"
        pattern="%style{%d{ISO8601_OFFSET_DATE_TIME_HHMM}}{white} %highlight{%-5level}{TRACE=white} %style{[%t][%logger]%notEmpty{[%markerSimpleName]}}{white} %highlight{%msg%n%xThrowable{2}}{TRACE=white}" />
    </Console>
  </Appenders>
  <Loggers>
    <Root level="WARN">
      <AppenderRef ref="Console" />
    </Root>
  </Loggers>
</Configuration>

[ppkarwasz]

Due to #2691 any problems with the throwable converters in 2.24.1, will no longer apply to 2.25.0.

In the current implementation, however, there is an off-by-one error: if I use %xThrowable{2}, I obtain a single stack trace line, instead of the expected two:

INFO An unexpected problem occurred, while doing foo.
java.lang.RuntimeException
	at eu.copernik.sandbox.MainTest.logAtInfo(MainTest.java:13) [test-classes/:?]

@vy, do you agree that the stack trace line count should not include the line with the exception message?

[garydgregory]

FWIW, my expectation was that the depth counts stack FRAMES, not lines, for BOTH the exception AND its causes.

[garydgregory]

I would like a setting that shows me EVERYTHING, no truncations, but that's likely a feature request 😉

[ppkarwasz]

I would like a setting that shows me EVERYTHING, no truncations, but that's likely a feature request 😉

Isn't that the default behavior of %throwable?

[garydgregory]

Well, no, that's part of the confusion in the docs: "full" and "complete" corresponds to the default Java (or Log4j?) behavior which truncates stack frames and writes "... 71 more". I want to see everything.

[vy]

In the current implementation, however, there is an off-by-one error: if I use %xThrowable{2}, I obtain a single stack trace line, instead of the expected two:

INFO An unexpected problem occurred, while doing foo.
java.lang.RuntimeException
	at eu.copernik.sandbox.MainTest.logAtInfo(MainTest.java:13) [test-classes/:?]

@vy, do you agree that the stack trace line count should not include the line with the exception message?

I am not able to follow, xEx{2} renders the associated Throwable and produces max. 2 lines – this is identical to the behavior that was in <=2.23.1. An important difference is that, in #3073, we switched prefixing the rendered stack trace from white space to newline.

[vy]

@garydgregory, this ticket is a duplicate of LOG4J2-3627, which is fixed in #2691 and the fix will be shipped with 2.25.0.

"full" and "complete" corresponds to the default Java (or Log4j?) behavior which truncates stack frames and
writes "... 71 more". I want to see everything.

I'd appreciate it if we can discuss this feature request either in the dev@ mailing list or GitHub Discussions first.

[ppkarwasz]

I am not able to follow, xEx{2} renders the associated Throwable and produces max. 2 lines – this is identical to the behavior that was in <=2.23.1. An important difference is that, in #3073, we switched prefixing the rendered stack trace from white space to newline.

The documentation says:

Outputs the first depth lines of the stack trace

Reading this I would expect to see the first depth stack trace elements. This interpretation is confirmed by the documentation of short:

Outputs the first line of the stack trace (analogous to %ex{1})

When I use short I get the exception message + the first stack trace element. So short currently works like %ex{2}.

I have never trimmed stack traces, so I don't know what users expect, but personally I find the numbering not intuitive. Also %ex{1} and %ex{2} means that no information about the causality chain will be printed, so the setting is useless for debugging.

[vy]

@ppkarwasz, in the documentation, it uses the stack trace expression consistently, it never talks about stack trace element. Note that a stack trace is not just composed of stack trace elements, but also labels (Caused by, Wrapped by and CIRCULAR REFERENCE, etc.) and exception messages, which consume from the line capacity too. Hence, IMO, it makes sense the depth limit caps "the rendered stack trace lines", not "the stack trace elements". Would you want me to explicitly state this difference in the docs?

[ppkarwasz]

Would you want me to explicitly state this difference in the docs?

Maybe you could say "Truncates the output if it exceeds depth lines".

Regarding %ex{short}, I believe that it should be equivalent to %n%ex{short.className}: %ex{short.message} or %n<output of Throwable.toString()>. Currently it prints the first 2 (not 1) lines of the stacktrace. If the Throwable.getMessage() contains new lines, this could not even contain the full message.

[garydgregory]

Why is this closed? It's a plain bug.

[ppkarwasz]

Why is this closed? It's a plain bug.

It is marked as duplicate, since it was fixed in #2691. See Volkan's comment:

this ticket is a duplicate of LOG4J2-3627, which is fixed in #2691 and the fix will be shipped with 2.25.0.