Consolidate stack trace rendering in Pattern Layout

[alan0428a]

This change target to fix LOG4J2-3627 and github issue https://github.com/apache/logging-log4j2/issues/1729

Checklist

• Base your changes on 2.x branch if you are targeting Log4j 2; use main otherwise
• ./mvnw verify succeeds (if it fails due to code formatting issues reported by Spotless, simply run ./mvnw spotless:apply and retry)
• Non-trivial changes contain an entry file in the src/changelog/.2.x.x directory
• Tests for the changes are provided
• Commits are signed (optional, but highly recommended)

[alan0428a]

Changes are based on the feedback in https://github.com/apache/logging-log4j2/pull/1137. However, as you might notice, there are similar methods in ThrowablePatternConverter and Throwableproxyrenderer, because of the package filtering added for %ex

Please let me know where to improve, thanks

[alan0428a]

Also I want to add more tests to cover the changes, but my Intellij IDEA shows below when I tried to run testException in ThrowableTest.

org.junit.jupiter.api.extension.ParameterResolutionException: No appender named List

	at org.apache.logging.log4j.core.test.junit.AppenderResolver.resolveParameter(AppenderResolver.java:50)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)

Also my ./mvnw verify also failed.

[INFO] Apache Log4j Core .................................. FAILURE
....
[ERROR] Failed to execute goal biz.aQute.bnd:bnd-baseline-maven-plugin:7.0.0:baseline (check-api-compat) on project log4j-core: An error occurred while calculating the baseline: Baseline problems detected.

Could you let me know how to fix it?

[vy]

@alan0428a, not to mention I am expecting to see several new tests. In particular, for %xEx{ [ "short" | depth]} and filter(packages).

[alan0428a]

Also add tests to cover the changes, please review when you have time.

[vy]

@alan0428a, could you also create a src/changelog/.2.x.x/fix_throwable_converter_issues.xml, please? See other fix_*.xml files in the folder for the file structure. Please keep the description short, but still informative – imagine you will be reading that line (among hundreds of others) in the release notes.

[ppkarwasz]

Note about the test failures: unfortunately we have about a dozen of flaky tests in our project (see the Develocity statistics for a list). The failures in those tests are not specific to this PR.

The failures in the Log4j Tag Library on the other hand seem connected to this PR and need to be investigated.

[alan0428a]

Just checked it's because before the PR, ThrowablePatternRender#formatOption serialize excpetion using Throwable#printStackTrace. But in the new implementation, I get the exception info using Throwable.getStackTrace and serialize using appendEntry, whose implementation is different from Throwable#printStackTrace.

The implementation in Throwable#printStackTrace is quite complicated, so I think it's better to get the exception info using Throwable#printStackTrace, instead of building our own implementation if we don't want to change the output format.

I am thinking the flow will be like(Just like the old way, but do not use String#split and add filter package)

1. Get exception info from `Throwable#printStackTrace`
2. Get `StringBuffer` from `StringWriter#getBuffer()`, which supports `indexOf()` since it extends `AbstractStringBuilder`
3. Use similar approach in `StringBuilders.truncateAfterDelimiter` but also append suffix, filter package and stop the loop when the line count reaches depth. 

Though the behavior is different from %rEx and %xEx(which processes through all lines then truncate), its "process and early stop" approach is same as the old implementation.

WDYT?

[vy]

Just checked it's because before the PR, ThrowablePatternRender#formatOption serialize excpetion using Throwable#printStackTrace. But in the new implementation, I get the exception info using Throwable.getStackTrace and serialize using appendEntry, whose implementation is different from Throwable#printStackTrace.

The implementation in Throwable#printStackTrace is quite complicated, so I think it's better to get the exception info using Throwable#printStackTrace, instead of building our own implementation if we don't want to change the output format.

I am thinking the flow will be like(Just like the old way, but do not use String#split and add filter package)

1. Get exception info from `Throwable#printStackTrace`
2. Get `StringBuffer` from `StringWriter#getBuffer()`, which supports `indexOf()` since it extends `AbstractStringBuilder`
3. Use similar approach in `StringBuilders.truncateAfterDelimiter` but also append suffix, filter package and stop the loop when the line count reaches depth. 

Though the behavior is different from %rEx and %xEx(which processes through all lines then truncate), its "process and early stop" approach is same as the old implementation.

@alan0428a, completely agreed with the idea that we should use Throwable#printStackTrace() wherever possible, i.e., in ThrowablePatternConverter (i.e., %ex) and RootThrowablePatternConverter (i.e., %rEx). The former can have a package-private Throwable rendering method (accepting packages and maxLineCount) that both can use. ExtendedThrowablePatternConverter (i.e., %xEx) needs to operate on a ThrowableProxy, hence there we need to roll out our own Throwable#printStackTrace().

[alan0428a]

@vy Actually %rEx and %xEx both operate on a ThrowableProxy in existing implementation. So only %ex needs to rely on Throwable#printStackTrace(). However, the output of Throwable#printStackTrace() looks like below:

java.lang.IllegalArgumentException: IllegalArgument
	at org.apache.logging.log4j.core.pattern.ThrowableTest.testConverter(ThrowableTest.java:77)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        (too long to paste)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:495)
Caused by: java.lang.NullPointerException: null pointer
	at org.apache.logging.log4j.core.pattern.ThrowableTest.testConverter(ThrowableTest.java:76)
	... 128 more

If we want to do filtering, we can only check if a line contains target package in options.getIgnorePackages().(Since we now we can only get the whole StringBuffer from StringWriter#getBuffer()) I am thinking the logic be like:

final int endIdx = buffer.indexOf(System.lineSeparator(), offset);
if (ignoreElement(buffer, options.getIgnorePackages(), offset, endIdx) {
...
}

private static boolean ignoreElement(final StringBuffer buffer, final List<String> ignorePackages, final int startIdx, final int endIdx) {
        if (ignorePackages != null) {
            final String line = buffer.subString(startIdx, endIdx);
            for (final String pkg : ignorePackages) {
                if (line.contains(pkg)) {
                    return true;
                }
            }
        }
        return false;
    }

Does this sound reasonable?

[vy]

@vy Actually %rEx and %xEx both operate on a ThrowableProxy in existing implementation.

I think this is a ~feature~ bug. %rEx should operate on the Throwable, just like %ex. Hence, I prefer this to be fixed.

So only %ex needs to rely on Throwable#printStackTrace(). However, the output of Throwable#printStackTrace() looks like below: ... If we want to do filtering, we can only check if a line contains target package in options.getIgnorePackages().

For one, this won't be exactly correct. You will be matching against the stack trace line, not the package name of the associated StackTraceElement. But I am not concerned about this loose end.

My main concern is, implementing packages filtering on a StringBuilder containing a stack trace won't be trivial. You not only need to filter lines, but also report them ala ThrowableProxyRenderer.appendSuppressedCount(). We will just be duplicating the effort that is already there for ThrowableProxyRenderer.

Even though I earlier supported the idea of "sticking to Throwable#printStackTrace() wherever possible", coming to think about it again... If a user provides either packages or maxLineCount, it is certain that they won't get a standard stack trace anymore. Given this, I suggest both %ex and %rEx delegate to ThrowableProxyRenderer (just like %xEx) iff either packages, maxLineCount, suffix, or lineSeparator is provided. This approach will have the following pros/cons:

1. All stack trace dump mangling will be consolidated at one place – Great!
2. %ex and %rEx will report package information unnecessarily – Acceptable (I will explain a fix for this!)
3. Allocation cost will slightly increase – Acceptable

Let me be more clear:

1. If either packages, maxLineCount, suffix, or lineSeparator is provided,
2. ThrowablePatternConverter will obtain a ThrowableProxy:

event.getThrownProxy() != null ? event.getThrownProxy() : new ThrowableProxy(event.getThrown())

3. RootThrowablePatternConverter, will find the root cause and wrap it with in ThrowableProxy:

Throwable rootCause = Throwables.getRootCause(event.getThrown());
new ThrowableProxy(rootCause);

4. Both ThrowablePatternConverter and RootThrowablePatternConverter will use ThrowableProxyRenderer with the obtained ThrowableProxy.

What about unsolicited package information?

If we consolidate all stack trace mangling to ThrowableProxyRenderer, %ex and %rEx will report package information too. We can fix this by adding an extra extendedClassInfoRendered boolean parameter to its formatWrapper(). This flag needs to be passed all the way down to ExtendedStackTraceElement#renderOn().

Feedback

@alan0428a, before starting to implement this, I really would like to hear your thoughts too. In the meantime, I will ask this to some other PMC members too.

Thanks!

@alan0428a, I can't thank you enough for this contribution and walking with us along this process. :bow: Please try to understand us for the thorough review process and see that it is not easy to come up with a good resolution, putting aside the difficulty of implementing that resolution. I am very very happy with interacting with you so far and please keep these contributions coming. It would be great to see you as a regular Log4j contributor! :heart_eyes:

[ppkarwasz]

@alan0428a, before starting to implement this, I really would like to hear your thoughts too. In the meantime, I will ask this to some other PMC members too.

Looks good to me. Actually nothing prevents ThrowablePatternConverter.getInstance() from returning an instance of ExtendedThrowablePatternConverter, so most of the logic can be migrated there.

[alan0428a]

@vy Thanks for your feedback! Actually I am happy we have this careful reveiw process, so that we have high standard codes.

Back to the topic, I also agree that this render logic should be in one place, since all renderer are doing similar things. But I am not sure if I unsderstand what ThrowableProxy really is and when it will be created in the LogEvent? I saw at xxxThrowablePatternConverter#format() we do conditions checking whether event.getThrownProxy() is null. But when will it be null?

For RootThrowablePatternConverter , I think the passed in ThrowableProxy already has the root cause. Do we need to wrap it like what you mentioned?

From the high level I guess I understand what we want to proceed, and I think it's a good resolution. Just there are some small questions may need your help to guide me here. Thanks!

[vy]

I saw at xxxThrowablePatternConverter#format() we do conditions checking whether event.getThrownProxy() is null. But when will it be null?

I presume, since ThrowableProxy et al. has been added after the incarnation of LogEvent, its implementation is optional for backward compatibility reasons. The default implementation (i.e., Log4jLogEvent) populates it dynamically when requested. Hence, we should first check if LogEvent#getThrownProxy() is not null, otherwise create one using ThrowableProxy::new.

For RootThrowablePatternConverter , I think the passed in ThrowableProxy already has the root cause. Do we need to wrap it like what you mentioned?

No, you're right, we don't need to. I confused the behaviour of Pattern Layout's %rEx with JSON Template Layout's exceptionRootCause.

[alan0428a]

@vy Just want to make sure we are on the same page.

So for xxxThrowablePatternConverter#format(), the existing implementation is that when event.getThrownProxy() is null, it calls its parent ThrowablePatternConverter#format(). And we want to change it to create one using ThrowableProxy::new when it's null then call ThrowableProxy#formatXxxStackTraceTo()?

As for ThrowablePatternConverter#format(), we want to create ThrowableProxy if options are not default, and delegate to ThrowableProxy for rendering.

[rgoers]

As I recall ThrowableProxy was introduced so that LogEvents could be remotely shipped to remote systems. We no longer support doing that kind of thing using Java Serialization. So I find myself wondering if we couldn't use this as PR as a way to get rid of ThrowableProxy altogether? That would force us to have all the formatting in either a helper or renderer class.

[vy]

@rgoers, I very much liked the idea of retiring ThrowableProxy. I analyzed the possibility of this. I will share my findings below.

What does Logback do?

AFAIK, Log4j's %xEx is added to match the same functionality in Logback. I examined Logback documentation and its source code on this:

1. Logback has disabled packaging data by default (since the 1.1.4 release published in February 2016, due to performance reasons)
2. Logback reports packaging information doesn't play nice with Netbeans
3. Logback deprecated ClassPackagingData in 2023-05-11

What does ThrowableProxy do?

• Helps with serialization – nobody would miss its absence
• Helps with capturing the class loader context and does this efficiently – i.e., the StackLocatorUtil.getCurrentStackTrace() call. This bit is important, in particular, during asynchronous logging. That is, the class loader et al. needs to be captured before the asynchronous barrier. But guess what, we don't do that! LogEvent#getThrownProxy() is called by the layout of the appender, i.e., after the asynchronous barrier, and it gets populated on demand. Put another way, ThrownProxy is populated by the request from layout, after asynchronous logging scheduled the task away from the original user thread.

Proposal: Create a new ThrowableRenderer class, rewire ThrowableProxyRenderer calls to this new class, and deprecate ThrowableProxy et al.

1. Create a new internal (package-private, etc.) ThrowableRenderer<C> class taking care of Throwable (not ThrowableProxy!) rendering such that:

package org.apache.logging.log4j.core.pattern;

// Note package-private class/ctor/method definitions for encapsulation!
class ThrowableRenderer<C> {

    ThrowableRenderer(
            Set<String> ignoredPackageNames,
            String stackTraceElementSuffix,
            String lineSeparator,
            int maxLineCount) {
        // Initialize package-private final fields...
    }

    // This is the method `Converter`s will be calling.
    //
    // Note the `final` modifier – subclasses should override the
    // `renderThrowable()` method accepting `C`.
    final void renderThrowable(StringBuilder buffer, Throwable throwable) {
        C context = createContext(throwable);
        renderThrowable(buffer, throwable, context);
    }

    // This will be overridden by `ExtendedThrowableRenderer` to pass the
    // map containing the `StackTraceElement`-to-packagingInformation cache.
    C createContext(Throwable throwable) {
        return null;
    }

    // This will be overridden by `RootThrowableRenderer` to
    // reverse the causal chain order.
    void renderThrowable(StringBuilder buffer, Throwable throwable, C context) {
        // Render `Throwable`...
    }

    // This will be overridden by `ExtendedThrowableRenderer` to
    // inject the packaging information cached in `context`.
    void renderStackTraceElement(
            StringBuilder buffer,
            StackTraceElement stackTraceElement,
            C context) {
        // Render `StackTraceElement`...
    }

}

2. Use an instance of ThrowableRenderer<Void> in ThrowablePatternConverter
3. Create the package-private RootThrowableRenderer class extending from ThrowableRenderer<Void> by overriding its renderThrowable(Throwable,Void) to reverse the causal chain rendering.
4. Use an instance of RootThrowableRenderer in RootThrowablePatternConverter
5. Create the package-private ExtendedThrowableRenderer class extending from ThrowableRenderer<PackagingInfoCache> such that:

class ExtendedThrowableRenderer extends ThrowableRenderer<PackagingInfoCache> {

    @Override
    PackagingInfoCache createContext(Throwable throwable) {
        // You need `StackLocatorUtil.getCurrentStackTrace()` and some other cache
        // structures used in `ThrowableProxyHelper.toExtendedStackTrace()`.
    }

    @Override
    void renderStackTraceElement(
            StringBuilder buffer,
            StackTraceElement element,
            PackagingInfoCache cache) {
        String location = cache.get(element);
        // Copy-paste from parent and inject `location` appropriately.
    }

    // Alternatively, instead of copy-pasting the body of `renderStackTraceElement()`
    // from the parent as described above, you can also make the parent logic reusable
    // by one more fine-grained (package-private static) method in the parent:
    static void renderStackTraceElement(
            StringBuilder buffer,
            StackTraceElement element,
            // You can pass location information in the suffix.
            // That is, `suffix = location + suffix`.
            String suffix,
            String newlineSeparator) {
        // ...
    }

}

7. Use an instance of ExtendedThrowableRenderer in ExtendedThrowablePatternConverter
8. Deprecate LogEvent#getThrownProxy()
9. Deprecate ThrowableProxy
10. Deprecate ExtendedStackTraceElement and ExtendedClassInfo
11. Remove ThrowableProxyRenderer
12. Double-check ExtendedThrowableRenderer performance (Refer to this recent related performance bug: #1214)
13. Revamp tests
14. Create a follow-up PR to
15. Cherry-pick changes from 2.x
16. Remove all deprecated methods and classes from main

Note that the proposed ThrowableRender doesn't use TextRenderer as its predecessor ThrowableProxyRenderer does.

Feedback

@alan0428a, @rgoers, @ppkarwasz, could you comment, please?

[ppkarwasz]

@vy,

1. Create a new _internal_ (package-private, etc.) `ThrowableRenderer<C>` class taking care of `Throwable` (not `ThrowableProxy`!) rendering such that:

I would rather retrofit PatternConverter with a generic parameter T to indicate the type of object supported by the converter. Then we could create:

• an internal PatternConverter<Throwable> implementation that prints standard stacktraces.
• if we need ever need it, in the future we could add a second configurable PatternConverter<Throwable> implementation that uses a list of PatternConverter<StackTraceElement> to format stack traces (e.g. add ANSI colors).

Such an architecture:

1. would be coherent with what JTL does with StackTraceElementResolver,
2. add more coherence to PL itself, since formatting stack traces and log events would use the same PatternConverter abstraction (instead of an ad-hoc TextRenderer).

Remark: Since 99% of PL users does not specify any throwable converter and given the complexity of the converter itself, I think we could move the configuration of the throwable converter from the pattern configuration attribute to a nested configuration element.

<PatternLayout pattern="%m%n">
    <ExtendedThrowableConverter stackTracePattern="%class.%method(%file:%line)"
                                maxLines="20"
                                ignorePackages="org.apache.logging.log4j"/>
</PatternLayout>

Seems much clearer to me than the current complex list of options of %xEx.

[vy]

I would rather retrofit PatternConverter with a generic parameter T to indicate the type of object supported by the converter.

@ppkarwasz, agreed, but that would be a breaking change, right? IMHO, it stretches the focus of this PR far too much. Let's just start with consolidating the existing Throwable-rendering logic.

<PatternLayout pattern="%m%n">
    <ExtendedThrowableConverter stackTracePattern="%class.%method(%file:%line)"
                                maxLines="20"
                                ignorePackages="org.apache.logging.log4j"/>

I liked this idea, but, again, IMHO, we better address it as a follow-up work.

[ppkarwasz]

@ppkarwasz, agreed, but that would be a breaking change, right? IMHO, it stretches the focus of this PR far too much. Let's just start with consolidating the existing Throwable-rendering logic.

According to BND, replacing PatternConverter with PatternConverter<T> is a backward compatible change. There are two converters that also implement ArrayPatternConverter and can therefore not be PatternConverter<LogEvent>, but worst case scenario we can use PatternConverter<Object> for all the current converters.

[alan0428a]

It seems to me this PR is more complicated then I thought and is more like refactoring now. But I will try my best to understand it.

I don't have feedback on deprecating ThrowableProxy, as you are more familiar with the historical background than I am.

// You need StackLocatorUtil.getCurrentStackTrace() and some other cache // structures used in ThrowableProxyHelper.toExtendedStackTrace().

I might need to dig more on this, I am not sure what stucture is needed. And I think this is only needed by %xEx pattern?

Note that the proposed ThrowableRender doesn't use TextRenderer as its predecessor ThrowableProxyRenderer does.

I don't follow on this. Where is this TextRenderer change coming from?

[vy]

It seems to me this PR is more complicated then I thought and is more like refactoring now. But I will try my best to understand it.

@alan0428a, thanks so much for your patience and perseverance. I will guide you throughout this process and will strive to keep the scope as minimal as possible, yet in the right direction.

If you agree with, you can send an email to me and I can create a guest account for you in the ASF Slack workspace. That can be a better communication medium to iterate faster on this issue.

Note that the proposed ThrowableRender doesn't use TextRenderer as its predecessor ThrowableProxyRenderer does.

I don't follow on this. Where is this TextRenderer change coming from?

It is a long story. In short, an ~over-engineering~ incomplete attempt to produce stack traces in multiple formats. The bottom line is, ThrowableProxyRenderer supported it, we won't in the new ThrowableRenderer, hence you don't need to worry about it.

[rgoers]

I do like Piotr's proposal of configuring the stack trace as a sub-element. However, I would do that as a separate follow-on item. The work being proposed here is already fairly involved. For now I would recommend following the steps Volkan outlined.

[github-actions[bot]]

Job	Requested goals	Build Tool Version	Build Outcome	Build Scan®
build-macos-latest	clean install	3.9.8	:white_check_mark:
build-ubuntu-latest	clean install	3.9.8	:white_check_mark:
build-windows-latest	clean install	3.9.8	:white_check_mark:

Generated by gradle/develocity-actions

[rgoers]

Well shucks, while you were in there it would be nice to resolve LOG4J2-2170 and add in the module information.

[vy]

Well shucks, while you were in there it would be nice to resolve LOG4J2-2170 and add in the module information.

@rgoers, that ticket is implicitly resolved too. I added tests for that and updated the changelog entry.

[vy]

This looks good to me, except the leading space that is added to each stack trace

@ppkarwasz, I implemented this, and it caused 99 test failures in log4j-core-test. I will implement this change in another PR.