Conversation
|
We need tests to accept a change like this. |
There was a problem hiding this comment.
Pull request overview
This PR aims to reduce duplicate ERROR log entries emitted by DefaultStackTraceFilterer by filtering stack traces for the full exception cause-chain without logging each cause separately, and logging the full stack trace only once for the top-level exception.
Changes:
- Extracted the filtering/trimming logic into a new private
doFilter(Throwable)method. - Updated recursive filtering to call
doFilter(...)when walking the cause chain. - Updated
filter(Throwable)to log conditionally (intended: once per top-level exception).
Comments suppressed due to low confidence (1)
grails-bootstrap/src/main/groovy/org/grails/exceptions/reporting/DefaultStackTraceFilterer.java:88
- In
filter(Throwable source, boolean recursive), the recursive walk callsdoFilter(current)starting withcurrent = source, and thenfilter(source)is invoked afterward. This filters the top-level exception twice and, more importantly, ensures the later log infilter(source)will observe an already-filtered stack trace. Consider starting the loop atsource.getCause()(filter causes only) so the top-level exception is filtered/logged exactly once infilter(source).
public Throwable filter(Throwable source, boolean recursive) {
if (recursive) {
Throwable current = source;
while (current != null) {
doFilter(current);
current = current.getCause();
}
}
return filter(source);
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
| public Throwable filter(Throwable source) { | ||
| if (shouldFilter) { | ||
| StackTraceElement[] trace = source.getStackTrace(); | ||
| List<StackTraceElement> newTrace = filterTraceWithCutOff(trace, cutOffPackage); | ||
|
|
||
| if (newTrace.isEmpty()) { | ||
| // filter with no cut-off so at least there is some trace | ||
| newTrace = filterTraceWithCutOff(trace, null); | ||
| } | ||
|
|
||
| // Only trim the trace if there was some application trace on the stack | ||
| // if not we will just skip sanitizing and leave it as is | ||
| if (!newTrace.isEmpty()) { | ||
| // We don't want to lose anything, so log it | ||
| boolean modified = doFilter(source); | ||
| if (modified) { | ||
| // Log the full stack trace once for the top-level exception (includes causes) | ||
| STACK_LOG.error(FULL_STACK_TRACE_MESSAGE, source); | ||
| StackTraceElement[] clean = new StackTraceElement[newTrace.size()]; | ||
| newTrace.toArray(clean); | ||
| source.setStackTrace(clean); | ||
| } |
There was a problem hiding this comment.
filter(Throwable source) currently calls doFilter(source) (which mutates source via setStackTrace) before logging FULL_STACK_TRACE_MESSAGE. That means the "Full Stack Trace" log is no longer the full/original trace, but the already-filtered trace. To preserve prior behavior and the PR description, log the exception before applying the filtered stack trace (e.g., have doFilter compute/return the cleaned trace without mutating, then apply after logging, or temporarily save/restore the original trace around the log call).
| if (shouldFilter) { | ||
| StackTraceElement[] trace = source.getStackTrace(); | ||
| List<StackTraceElement> newTrace = filterTraceWithCutOff(trace, cutOffPackage); | ||
|
|
||
| if (newTrace.isEmpty()) { | ||
| // filter with no cut-off so at least there is some trace | ||
| newTrace = filterTraceWithCutOff(trace, null); | ||
| } | ||
|
|
||
| // Only trim the trace if there was some application trace on the stack | ||
| // if not we will just skip sanitizing and leave it as is | ||
| if (!newTrace.isEmpty()) { | ||
| // We don't want to lose anything, so log it | ||
| boolean modified = doFilter(source); | ||
| if (modified) { | ||
| // Log the full stack trace once for the top-level exception (includes causes) | ||
| STACK_LOG.error(FULL_STACK_TRACE_MESSAGE, source); | ||
| StackTraceElement[] clean = new StackTraceElement[newTrace.size()]; | ||
| newTrace.toArray(clean); | ||
| source.setStackTrace(clean); | ||
| } |
There was a problem hiding this comment.
This change modifies when/how often the StackTrace logger logs (STACK_LOG.error(...)) during recursive filtering, but existing specs (e.g., grails-core/src/test/.../StackTraceFiltererSpec.groovy) only assert the sanitized stack trace contents and don't cover log emission/count. Adding a test that captures the StackTrace logger output and asserts a single "Full Stack Trace" entry for filter(e, true) would help prevent regressions.
| boolean modified = doFilter(source); | ||
| if (modified) { | ||
| // Log the full stack trace once for the top-level exception (includes causes) | ||
| STACK_LOG.error(FULL_STACK_TRACE_MESSAGE, source); |
There was a problem hiding this comment.
Isn't this a different meaning now? Before it would have been the full stack trace while now it's the filtered. Wouldn't a better solution be to set the logging to trace or something for these detailed stack traces ? Instead of this change why not disable STACK_LOG if you don't want this output?
|
The more I have thought about this, the more I realize this is not a bug fix. This is a feature - we are not trimming stacktraces that got longer due to groovy 4. We are instead hiding traces that get logged multiple times. I think the original behavior needs to stay and we need to make the new feature opt in. |
Fix duplicate stack trace logging in DefaultStackTraceFilterer
When an exception occurs in a Grails controller, the same error is logged multiple times to the
StackTracelogger. For a typicalInvocationTargetExceptionwrapping aRuntimeException, this produces 3-4 separate ERROR log entries for a single request:StackTracelogger: Full stack trace of the wrapper exceptionStackTracelogger: Full stack trace of the root causeStackTracelogger: Full stack trace of the wrapper again (condensed)GrailsExceptionResolverlogger: The exception with request contextEntries 1-3 all come from
DefaultStackTraceFilterer.filter(). Thefilter(Throwable source, boolean recursive)method walks thecause chain and calls
filter(Throwable source)for each throwable. Butfilter(Throwable source)logs the full stack trace viaSTACK_LOG.error(FULL_STACK_TRACE_MESSAGE, source)every time it trims a trace — so each cause in the chain gets its own log entry.This is compounded by the fact that
GrailsExceptionResolver.logStackTrace()then logs the exception a final time with requestcontext. The filterer and the resolver were written independently — the filterer doesn't know the resolver will also log, and the
resolver doesn't know the filterer already logged.
Fix
Extract the stack trace trimming logic into a private
doFilter(Throwable)method that filters without logging. The recursive walkcalls
doFilter()for each cause in the chain. The publicfilter(Throwable source)method callsdoFilter()and then logs thefull stack trace once for the top-level exception (which naturally includes its causes in the log output).
This reduces the
StackTracelogger output from N entries (one per cause) to 1 entry, while preserving all existing behavior:StackTraceFiltererinterface is unchangedGrailsExceptionResolversubclasses are unaffected