Configurable exception pattern for log4j2

[HaloFour]

Allows configuring a throwable pattern to be used when serializing exceptions associated with the current log event. For example, given the pattern %ex{4} the stack trace of the exception will be limited to the first 4 lines. Should support any pattern supported by log4j2 including filters to suppress stack frames from specific packages.

[HaloFour]

Decided to try to pick this back up. We're already running into issues with our Elastic storage given the size of our stack traces (Spring WebFlux application, a stack can easily exceed 50k). Instead of trying to build something completely new, as I did before, I decided to piggyback off of what is offered by log4j2.

[apmmachine]

💚 Build Succeeded

the below badges are clickable and redirect to their specific view in the CI or DOCS

Expand to view the summary

Build stats

• Start Time: 2022-04-28T04:01:11.091+0000

• Duration: 7 min 5 sec

Test stats 🧪

Test	Results
Failed	0
Passed	232
Skipped	0
Total	232

🤖 GitHub comments

To re-run your PR in the CI, just comment with:

• /test : Re-trigger the build.

• run elasticsearch-ci/docs : Re-trigger the docs validation. (use unformatted text in the comment!)

[eyalkoren]

@HaloFour thanks for your contribution!
Would the approach proposed in #167 meet your needs?

[eyalkoren]

@HaloFour Just saw your comment on #167. I plan to dedicate some time for ecs-logging fixes/enhancements and release in the coming weeks, including #167. If it does what you need, can we close this PR?

[HaloFour]

@eyalkoren

Thanks for checking out this PR!

Unfortunately I don't believe #167 meets my needs. I'm looking for more control over how the exception stack trace is rendered beyond filtering out unwanted frames by package. For example, my preference is to render exceptions root-first, and to limit the number of total frames rendered, which is possible with the %rEx{depth} pattern. This PR also allows developers to use any custom plugin pattern converter to render their exceptions any way they want.

[eyalkoren]

OK, makes sense, thanks!
We got this on the radar now. Once I get available for that, we will see how we progress.
Does this replace #105? Can we close it?

[HaloFour]

Does this replace #105? Can we close it?

Yep, I just closed it, sorry for letting it hang out there for so long. 😅

[HaloFour]

To answer your question about stack-as-array, it should be supported by this PR. I use the PatternFormatters to populate a StringBuilder and then pass the resulting String to EcsJsonSerializer#serializeException. If stackTraceAsArray is true it should split that String up by newline into array elements. I can look at adding a few more test suites to cover these cases.

Maybe it's worth looking to change those methods in EcsJsonSerializer to accept CharSequence so you could pass StringBuilder directly without having to allocate an intermediate String?

[HaloFour]

Maybe it's worth looking to change those methods in EcsJsonSerializer to accept CharSequence so you could pass StringBuilder directly without having to allocate an intermediate String?

Took a stab at it: #178

Can be considered entirely independently from this PR.

Also rewrote EcsJsonSerializer#formatStackTraceAsArray as Pattern#split internally does a bunch of allocations.

[eyalkoren]

@HaloFour looks good, let's go for it!
Please do add a test for stack trace as array, as you proposed, as well as other use cases you think we should cover.

[HaloFour]

@eyalkoren

Please do add a test for stack trace as array, as you proposed, as well as other use cases you think we should cover.

Sorry, got distracted.

I started down this path but I recall having issues where the schema to which the JSON is compared expects the error.stack_trace to be a string so it was failing validation which is enforced in core. Also wasn't sure the best route to have separate tests testing separate log configurations without making some changes to the entire suite.

[eyalkoren]

I started down this path but I recall having issues where the schema to which the JSON is compared expects the error.stack_trace to be a string so it was failing validation which is enforced in core.

Once we have a test we can see the error and either fix the validation if necessary, or realize what we are doing wrong. Without seeing the error, I can't say anything about that, so start by adding the test that does something and expects a specific behavior. If it fails and this is indeed the expected behavior, we will either fix the validation or the implementation later.

Also wasn't sure the best route to have separate tests testing separate log configurations without making some changes to the entire suite.

Changing the base test is a good idea if all frameworks can benefit from it. For example, we now have AbstractEcsLoggingTest#testLogException, if we have another one like AbstractEcsLoggingTest#testLogExceptionWithStackAsArray, that would be awesome! You may achieve that by adding an abstract method to AbstractEcsLoggingTest:

protected abstract void setStackTraceAsArray();

which each concrete implementation will apply to its own formatter. Note that all concrete tests that subclass this abstract test use @BeforeEach to set up the formatter, so if you keep a reference to it, you may do it this way.

If this is specific to a single framework, you can either extend the abstract test (as I just did for JUL for example), or add a separate test.

I hope this helps.

[felixbarny]

Instead of getAndValidateLastLogLine, you can call getLastLogLine to skip the validation.

See also

ecs-logging-java/logback-ecs-encoder/src/test/java/co/elastic/logging/logback/EcsEncoderWithStacktraceAsArrayTest.java

Line 70 in 23d5bd6

JsonNode log = getLastLogLine();

[HaloFour]

Thanks for the pointers, let me know if this helps.

[eyalkoren]

Very nice, thanks!
Some minor comments.
The custom converter test is awesome! However, the other tests should preferably rely on the builtin converter.
I think we could use the stack as array test in the entire suite, but I can do it later (through this PR or other). If you tried and found reasons not to, please let me know.

[eyalkoren]

Suggested change

	assertThat(log.get("error.message")).isNull();
	assertThat(log.get("error.message")).isNull();
	assertThat(log.get("error.stack_trace").textValue()).isEqualTo("java.lang.RuntimeException\nSTACK_TRACE!");

(didn't actually test that, but based on code - we need to test this else branch as well)

[eyalkoren]

Why use the custom one and not rely these tests on the default pattern converter that is already configured through the superclass? Unless there's a good reason, I prefer to here what most users will use by default.

[HaloFour]

I can do that, I was using the custom converter to keep the stack traces predictable as I don't really want to be testing whatever log4j2 does under the covers (beyond confirming that it works anyway). I'll split the custom converter to its own test and use the built-in ones for these tests.

[eyalkoren]

It's already tested through EcsLayoutWithExceptionPatternTest, so what do you mean split further?
I understand the need for consistency without relying on log4j internals, but maybe you can use the builtin converter to achieve exactly that - filter out stack trace elements that are not yours and limit to only 3. Can you do that?

[HaloFour]

It's already tested through EcsLayoutWithExceptionPatternTest, so what do you mean split further?

You're right, I did, too much multitasking this week. 😅

I understand the need for consistency without relying on log4j internals, but maybe you can use the builtin converter to achieve exactly that - filter out stack trace elements that are not yours and limit to only 3. Can you do that?

Definitely, I'll try to get a commit up shortly.

[eyalkoren]

Looks good, thanks!
Please also apply my suggestions, unless there is a reason not to.