diff --git a/grails-bootstrap/src/main/groovy/org/grails/exceptions/reporting/DefaultStackTraceFilterer.java b/grails-bootstrap/src/main/groovy/org/grails/exceptions/reporting/DefaultStackTraceFilterer.java index 38c0235706b..88ff6247821 100644 --- a/grails-bootstrap/src/main/groovy/org/grails/exceptions/reporting/DefaultStackTraceFilterer.java +++ b/grails-bootstrap/src/main/groovy/org/grails/exceptions/reporting/DefaultStackTraceFilterer.java @@ -33,6 +33,14 @@ */ public class DefaultStackTraceFilterer implements StackTraceFilterer { public static final String STACK_LOG_NAME = "StackTrace"; + /** + * Dedicated logger for exception stack traces. The filterer itself no longer writes + * to it — exception logging is driven by {@code GrailsExceptionResolver}, which emits + * to this logger in addition to its own request-context log entry when + * {@code grails.exceptionresolver.logFullStackTrace} is enabled. Exposed as a public + * constant so that subclasses and logback configurations can reference the logger + * name symbolically. + */ public static final Log STACK_LOG = LogFactory.getLog(STACK_LOG_NAME); private static final String[] DEFAULT_INTERNAL_PACKAGES = new String[] { @@ -81,32 +89,32 @@ public Throwable filter(Throwable source, boolean recursive) { if (recursive) { Throwable current = source; while (current != null) { - current = filter(current); + filter(current); current = current.getCause(); } + return source; } return filter(source); } public Throwable filter(Throwable source) { - if (shouldFilter) { - StackTraceElement[] trace = source.getStackTrace(); - List newTrace = filterTraceWithCutOff(trace, cutOffPackage); + if (!shouldFilter) { + return source; + } + StackTraceElement[] trace = source.getStackTrace(); + List newTrace = filterTraceWithCutOff(trace, cutOffPackage); - if (newTrace.isEmpty()) { - // filter with no cut-off so at least there is some trace - newTrace = filterTraceWithCutOff(trace, null); - } + 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 - STACK_LOG.error(FULL_STACK_TRACE_MESSAGE, source); - StackTraceElement[] clean = new StackTraceElement[newTrace.size()]; - newTrace.toArray(clean); - source.setStackTrace(clean); - } + // 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()) { + StackTraceElement[] clean = new StackTraceElement[newTrace.size()]; + newTrace.toArray(clean); + source.setStackTrace(clean); } return source; } diff --git a/grails-bootstrap/src/main/groovy/org/grails/exceptions/reporting/StackTraceFilterer.java b/grails-bootstrap/src/main/groovy/org/grails/exceptions/reporting/StackTraceFilterer.java index ff0d9b6786f..304b329c583 100644 --- a/grails-bootstrap/src/main/groovy/org/grails/exceptions/reporting/StackTraceFilterer.java +++ b/grails-bootstrap/src/main/groovy/org/grails/exceptions/reporting/StackTraceFilterer.java @@ -26,6 +26,12 @@ */ public interface StackTraceFilterer { + /** + * Message used as the header for full stack trace log entries emitted on the + * dedicated {@code StackTrace} logger. The filterer itself does not log; + * {@code GrailsExceptionResolver} writes the entry when + * {@code grails.exceptionresolver.logFullStackTrace} is enabled. + */ String FULL_STACK_TRACE_MESSAGE = "Full Stack Trace:"; String SYS_PROP_DISPLAY_FULL_STACKTRACE = "grails.full.stacktrace"; diff --git a/grails-core/src/main/groovy/grails/config/Settings.groovy b/grails-core/src/main/groovy/grails/config/Settings.groovy index 004c66acede..b94754381ce 100644 --- a/grails-core/src/main/groovy/grails/config/Settings.groovy +++ b/grails-core/src/main/groovy/grails/config/Settings.groovy @@ -236,6 +236,13 @@ interface Settings { * The parameters to exclude from logging */ String SETTING_EXCEPTION_RESOLVER_PARAM_EXCLUDES = 'grails.exceptionresolver.params.exclude' + /** + * Whether the exception resolver should also emit the exception on the separate + * {@code StackTrace} logger in addition to its own request-context log entry. + * Defaults to {@code false}; set to {@code true} to restore the historical two-logger + * behaviour, which allows routing the trace to a separate appender via logback config. + */ + String SETTING_LOG_FULL_STACKTRACE = 'grails.exceptionresolver.logFullStackTrace' /** * The class to use for stacktrace filtering. Should be an instanceof {@link org.grails.exceptions.reporting.StackTraceFilterer} */ diff --git a/grails-core/src/test/groovy/org/grails/exception/reporting/StackTraceFiltererSpec.groovy b/grails-core/src/test/groovy/org/grails/exception/reporting/StackTraceFiltererSpec.groovy index 36affcd706d..d4819bd541f 100644 --- a/grails-core/src/test/groovy/org/grails/exception/reporting/StackTraceFiltererSpec.groovy +++ b/grails-core/src/test/groovy/org/grails/exception/reporting/StackTraceFiltererSpec.groovy @@ -21,102 +21,202 @@ package org.grails.exception.reporting import org.grails.exceptions.reporting.DefaultStackTraceFilterer import spock.lang.Specification +import org.grails.exceptions.reporting.StackTraceFilterer + class StackTraceFiltererSpec extends Specification { - private filterer = new DefaultStackTraceFilterer() - private gcl = new GroovyClassLoader() + StackTraceFilterer filterer = new DefaultStackTraceFilterer() + ClassLoader gcl = new GroovyClassLoader() - void "Test basic filter"() { - given: "A controller that should throw a MissingPropertyException" - def cls = gcl.parseClass(''' -package test + def 'retains application frames when filtering a stack trace'() { + given: 'a controller action that raises a missing property exception' + def controller = gcl.parseClass(''' + package test -class FooController { - def show = { - display() - } + class FooController { + def show = { + display() + } - void display() { - notHere - } -} -''') + void display() { + notHere + } + } + ''').getDeclaredConstructor().newInstance() - when: "The stack trace is filtered with custom packages" - filterer.setCutOffPackage("org.spockframework.util") - Throwable exception - try { - cls.getDeclaredConstructor().newInstance().show() - } catch (e) { - filterer.filter(e) - exception = e - } - - then: "Only valid stack elements are retained" - exception != null + when: 'the exception stack trace is filtered' + Throwable exception = null + try { + controller['show']() + } catch (e) { + filterer.filter(e) + exception = e + } - when: - StackTraceElement[] stackTraces = exception.stackTrace + then: 'the exception is available for inspection' + exception != null - then: - stackTraces.find { it.className == 'test.FooController' && it.lineNumber == 10 } - stackTraces.find { it.className.startsWith('test.FooController') && it.lineNumber == 6 } + and: 'the controller action and helper method frames remain in the filtered stack trace' + with(exception.stackTrace) { + it.find { it.className == 'test.FooController' && it.lineNumber == 10 } + it.find { it.className.startsWith('test.FooController') && it.lineNumber == 6 } + } } - void "Test deep filter"() { - given: "A controller that calls a service and rethrows an exception" - def cls = gcl.parseClass(''' -package test + def 'filter does not emit a StackTrace log entry for a single throwable'() { + given: 'captured System.err' + def originalErr = System.err + def baos = new ByteArrayOutputStream() + System.setErr(new PrintStream(baos, true)) -class FooController { - def fooService = new FooService() - def show = { - display() - } + and: 'an exception whose stack trace mixes application and internal frames' + def exception = new RuntimeException('boom') + exception.stackTrace = [ + new StackTraceElement('test.FooController', 'show', 'FooController.groovy', 6), + new StackTraceElement('java.lang.reflect.Method', 'invoke', 'Method.java', 580) + ] as StackTraceElement[] - void display() { - try { - fooService.notThere() - } - catch(e) { - throw new RuntimeException("Bad things happened", e) - } + when: 'the exception is filtered' + filterer.filter(exception) + then: "no 'Full Stack Trace:' entry is emitted by the filterer" + System.err.flush() + !baos.toString().contains('Full Stack Trace:') + + cleanup: + System.setErr(originalErr) } -} -class FooService { - void doStuff() { - notThere() - } -} -''') - when: "The stack trace is filtered with custom packages" - filterer.setCutOffPackage("org.spockframework.util") - Throwable exception + def 'retains controller frames across wrapped exceptions during recursive filtering'() { + given: 'a controller action that wraps a failure triggered during service interaction' + def controller = gcl.parseClass(''' + package test + + class FooController { + def fooService = new FooService() + def show = { + display() + } + + void display() { + try { + fooService.notThere() + } + catch(e) { + throw new RuntimeException("Bad things happened", e) + } + + } + } + class FooService { + void doStuff() { + notThere() + } + } + ''').getDeclaredConstructor().newInstance() + + when: 'recursive filtering is applied to the exception' + Throwable exception = null try { - cls.getDeclaredConstructor().newInstance().show() + controller['show']() } catch (e) { filterer.filter(e, true) - println getExceptionContents(e) exception = e } - then: "Only valid stack elements are retained" + then: 'the wrapped exception is available for inspection' exception != null - when: - StackTraceElement[] stackTraces = exception.stackTrace + and: 'the filtered stack trace retains the controller frames for the wrapper and action' + with(exception.stackTrace) { + it.find { it.className == 'test.FooController' && it.lineNumber == 15 } + it.find { it.className.startsWith('test.FooController') && it.lineNumber == 7 } + } + } + + def 'filter does not emit a StackTrace log entry when walking the cause chain'() { + given: 'captured System.err' + def originalErr = System.err + def baos = new ByteArrayOutputStream() + System.setErr(new PrintStream(baos, true)) + + and: 'a wrapped exception whose wrapper and cause mix application and internal frames' + def rootCause = new IllegalStateException('root cause') + rootCause.stackTrace = [ + new StackTraceElement('test.FooService', 'doStuff', 'FooService.groovy', 3), + new StackTraceElement('java.lang.reflect.Method', 'invoke', 'Method.java', 580) + ] as StackTraceElement[] + + def exception = new RuntimeException('boom', rootCause) + exception.stackTrace = [ + new StackTraceElement('test.FooController', 'show', 'FooController.groovy', 6), + new StackTraceElement('java.lang.reflect.Method', 'invoke', 'Method.java', 580) + ] as StackTraceElement[] + + when: 'recursive filtering is applied to the top-level exception' + filterer.filter(exception, true) + + then: "no 'Full Stack Trace:' entry is emitted for any throwable in the chain" + System.err.flush() + !baos.toString().contains('Full Stack Trace:') + + cleanup: + System.setErr(originalErr) + } - then: - stackTraces.find { it.className == 'test.FooController' && it.lineNumber == 15 } - stackTraces.find { it.className.startsWith('test.FooController') && it.lineNumber == 7 } + def 'recursive filtering visits every throwable in the cause chain and sanitizes each'() { + given: 'a cause chain with both application and internal stack frames' + def filterer = new CountingStackTraceFilterer() + def rootCause = new IllegalStateException('root cause') + rootCause.stackTrace = [ + new StackTraceElement('test.FooService', 'doStuff', 'FooService.groovy', 3), + new StackTraceElement('org.codehaus.groovy.runtime.InvokerHelper', 'invokeMethod', 'InvokerHelper.java', 12) + ] as StackTraceElement[] + + def wrappedCause = new RuntimeException('wrapped cause', rootCause) + wrappedCause.stackTrace = [ + new StackTraceElement('test.FooController', 'display', 'FooController.groovy', 11), + new StackTraceElement('org.codehaus.groovy.runtime.callsite.CallSiteArray', 'defaultCall', 'CallSiteArray.java', 15) + ] as StackTraceElement[] + + def exception = new RuntimeException('top level', wrappedCause) + exception.stackTrace = [ + new StackTraceElement('test.FooController', 'show', 'FooController.groovy', 7), + new StackTraceElement('org.codehaus.groovy.runtime.ScriptBytecodeAdapter', 'unwrap', 'ScriptBytecodeAdapter.java', 20) + ] as StackTraceElement[] + + when: 'recursive filtering is applied to the top-level exception' + filterer.filter(exception, true) + + then: 'filter is invoked once per throwable in the cause chain, in cause-chain order' + filterer.singleExceptionFilterInvocations == 3 + filterer.filteredSources == [exception, wrappedCause, rootCause] + + and: 'application stack frames are retained across the full cause chain' + with(exception) { + stackTrace*.className == ['test.FooController'] + stackTrace*.lineNumber == [7] + cause.stackTrace*.className == ['test.FooController'] + cause.stackTrace*.lineNumber == [11] + cause.cause.stackTrace*.className == ['test.FooService'] + cause.cause.stackTrace*.lineNumber == [3] + } } - private String getExceptionContents(Throwable e) { - final sw = new StringWriter() - def pw = new PrintWriter(sw) - e.printStackTrace pw - return sw.toString() + private static class CountingStackTraceFilterer extends DefaultStackTraceFilterer { + + int singleExceptionFilterInvocations + List filteredSources = [] + + CountingStackTraceFilterer() { + super(true) + } + + @Override + Throwable filter(Throwable source) { + singleExceptionFilterInvocations++ + filteredSources << source + super.filter(source) + } } } diff --git a/grails-doc/src/en/guide/conf/config/logging/loggingFullStackTraces.adoc b/grails-doc/src/en/guide/conf/config/logging/loggingFullStackTraces.adoc new file mode 100644 index 00000000000..74703c56a5f --- /dev/null +++ b/grails-doc/src/en/guide/conf/config/logging/loggingFullStackTraces.adoc @@ -0,0 +1,88 @@ +//// +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 + +https://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. +//// + +When a request-handling exception reaches `GrailsExceptionResolver`, Grails emits a single log record to the +`org.grails.web.errors.GrailsExceptionResolver` logger at `ERROR` level. That record contains the HTTP method and +request URI alongside a _filtered_ stack trace — framework internals such as `java.lang.reflect`, `jakarta.servlet`, +`org.codehaus.groovy.runtime`, and similar dispatch/plumbing frames are trimmed out so that application code is the +first thing visible on the trace. + +For most operational use the filtered trace is what you want: it surfaces the application frames that actually matter +and keeps the log readable. For cases that need the untrimmed trace — routing the raw frames to a separate audit +file, correlating with an APM tool, or debugging dispatcher internals — Grails exposes an opt-in: + +[source, yaml] +.grails-app/conf/application.yml +---- +grails: + exceptionresolver: + logFullStackTrace: true +---- + +The setting defaults to `false`. + +When enabled, Grails emits an additional log record to a dedicated logger named `StackTrace`, containing the +_unfiltered_ stack trace as it was captured at throw time. This record is written _before_ the filter step runs, +so no frames are lost. Each request-handling exception therefore produces two log records: + +* A `StackTrace` logger record with the full, unfiltered trace (header `Full Stack Trace:`). +* A `GrailsExceptionResolver` logger record with the filtered trace and the request-context headline +(` occurred when processing request: [] `). + +The two records carry different trace content — that is the value of the opt-in. The `StackTrace` record includes +every reflection, dispatch, and servlet frame; the `GrailsExceptionResolver` record shows only application code. + +==== Routing the StackTrace Logger To a Separate Appender + +Enabling `logFullStackTrace` alone will cause the unfiltered trace to appear on whatever appender the root logger +is configured with — typically the console — in addition to the filtered trace from the resolver logger. If that is +not what you want, pair the opt-in with a Logback configuration that routes the `StackTrace` logger to its own +appender and disables additivity so it does not bubble up to the root: + +[source, xml] +.grails-app/conf/logback.xml +---- + + logs/stacktraces.log + + %date %msg%n%ex%n + + + + + + +---- + +With this configuration the unfiltered trace is written only to `logs/stacktraces.log`, which you can rotate and +retain independently. The console continues to show the concise, filtered resolver record as before. + +==== Suppressing the StackTrace Logger + +Setting the `StackTrace` logger level to `OFF` in Logback makes the opt-in a no-op, regardless of the +`logFullStackTrace` property value: + +[source, xml] +.grails-app/conf/logback.xml +---- + +---- + +This is useful if the property is enabled in a shared `application.yml` but a particular environment needs to +silence the extra record. diff --git a/grails-doc/src/en/guide/index.adoc b/grails-doc/src/en/guide/index.adoc index 323a3efd2eb..588a469b2a3 100644 --- a/grails-doc/src/en/guide/index.adoc +++ b/grails-doc/src/en/guide/index.adoc @@ -165,6 +165,11 @@ include::conf/config/logging/loggerName.adoc[] include::conf/config/logging/maskingRequestParametersFromStacktraceLogs.adoc[] +[[loggingFullStackTraces]] +===== Logging Full Stack Traces + +include::conf/config/logging/loggingFullStackTraces.adoc[] + [[externalLoggingConfiguration]] ===== External Logging Configuration diff --git a/grails-doc/src/en/guide/toc.yml b/grails-doc/src/en/guide/toc.yml index e2aa4687128..9b04b5e7118 100644 --- a/grails-doc/src/en/guide/toc.yml +++ b/grails-doc/src/en/guide/toc.yml @@ -52,6 +52,7 @@ conf: title: Logging loggerName: Logger Names maskingRequestParametersFromStacktraceLogs: Masking Request Parameters From Stacktrace Logs + loggingFullStackTraces: Logging Full Stack Traces externalLoggingConfiguration: External Configuration File configGORM: GORM proxyConfig: Configuring an HTTP proxy diff --git a/grails-web-mvc/src/main/groovy/org/grails/web/errors/GrailsExceptionResolver.java b/grails-web-mvc/src/main/groovy/org/grails/web/errors/GrailsExceptionResolver.java index 9d41a20e928..950df66ab4f 100644 --- a/grails-web-mvc/src/main/groovy/org/grails/web/errors/GrailsExceptionResolver.java +++ b/grails-web-mvc/src/main/groovy/org/grails/web/errors/GrailsExceptionResolver.java @@ -89,6 +89,8 @@ public ModelAndView resolveException(HttpServletRequest request, HttpServletResp ex = findWrappedException(ex); + logFullStackTraceIfEnabled(ex); + filterStackTrace(ex); ModelAndView mv = super.resolveException(request, response, handler, ex); @@ -261,6 +263,24 @@ protected void logStackTrace(Exception e, HttpServletRequest request) { LOG.error(getRequestLogMessage(e, request), e); } + /** + * When the {@code grails.exceptionresolver.logFullStackTrace} property is enabled, + * emits the unfiltered stack trace to the dedicated {@code StackTrace} logger. + * Must be invoked before {@link #filterStackTrace(Exception)} — once the + * filterer calls {@code setStackTrace(clean)}, the original frames are gone and + * this method can only log the already-trimmed trace. + */ + protected void logFullStackTraceIfEnabled(Exception e) { + if (shouldLogFullStackTrace()) { + DefaultStackTraceFilterer.STACK_LOG.error(StackTraceFilterer.FULL_STACK_TRACE_MESSAGE, e); + } + } + + protected boolean shouldLogFullStackTrace() { + Config config = grailsApplication != null ? grailsApplication.getConfig() : null; + return config != null && config.getProperty(Settings.SETTING_LOG_FULL_STACKTRACE, Boolean.class, false); + } + protected Exception findWrappedException(Exception e) { if ((e instanceof InvokerInvocationException) || (e instanceof GrailsMVCException)) { Throwable t = getRootCause(e); diff --git a/grails-web-mvc/src/test/groovy/org/grails/web/errors/GrailsExceptionResolverSpec.groovy b/grails-web-mvc/src/test/groovy/org/grails/web/errors/GrailsExceptionResolverSpec.groovy index 0ef3ea062c9..6e38c6d3276 100644 --- a/grails-web-mvc/src/test/groovy/org/grails/web/errors/GrailsExceptionResolverSpec.groovy +++ b/grails-web-mvc/src/test/groovy/org/grails/web/errors/GrailsExceptionResolverSpec.groovy @@ -18,8 +18,11 @@ */ package org.grails.web.errors +import grails.config.Config +import grails.core.GrailsApplication import grails.web.mapping.UrlMappingsHolder import grails.web.mapping.exceptions.UrlMappingException +import org.grails.exceptions.reporting.DefaultStackTraceFilterer import org.springframework.mock.web.MockHttpServletRequest import spock.lang.Specification @@ -43,4 +46,98 @@ class GrailsExceptionResolverSpec extends Specification { noExceptionThrown() params.isEmpty() } -} \ No newline at end of file + + void "logStackTrace emits only the resolver log"() { + given: "Captured System.err" + def originalErr = System.err + def baos = new ByteArrayOutputStream() + System.setErr(new PrintStream(baos, true)) + + and: "A resolver with no grailsApplication wired" + def resolver = new GrailsExceptionResolver() + def request = new MockHttpServletRequest('GET', '/test') + def exception = new RuntimeException('boom') + + when: + resolver.logStackTrace(exception, request) + + then: "Only the GrailsExceptionResolver logger emits; StackTrace logger is silent" + System.err.flush() + def captured = baos.toString() + captured.contains('o.g.web.errors.GrailsExceptionResolver') || + captured.contains('org.grails.web.errors.GrailsExceptionResolver') + !captured.contains('ERROR StackTrace ') + + cleanup: + System.setErr(originalErr) + } + + void "logFullStackTraceIfEnabled is a no-op when the opt-in property is unset"() { + given: "Captured System.err" + def originalErr = System.err + def baos = new ByteArrayOutputStream() + System.setErr(new PrintStream(baos, true)) + + and: "A resolver with no grailsApplication wired" + def resolver = new GrailsExceptionResolver() + def exception = new RuntimeException('boom') + + when: + resolver.logFullStackTraceIfEnabled(exception) + + then: "No StackTrace log entry is emitted" + System.err.flush() + !baos.toString().contains('ERROR StackTrace ') + + cleanup: + System.setErr(originalErr) + } + + void "logFullStackTraceIfEnabled emits the unfiltered trace when opt-in is enabled, and filterStackTrace then removes internal frames so the resolver log only sees the filtered trace"() { + given: "Captured System.err" + def originalErr = System.err + def baos = new ByteArrayOutputStream() + System.setErr(new PrintStream(baos, true)) + + and: "A resolver whose config opts in to full stack trace logging" + def config = Mock(Config) + config.getProperty('grails.exceptionresolver.logFullStackTrace', Boolean, false) >> true + config.getProperty('grails.exceptionresolver.logRequestParameters', Boolean, _) >> false + config.getProperty('grails.logging.stackTraceFiltererClass', Class, _) >> + DefaultStackTraceFilterer + def grailsApp = Mock(GrailsApplication) + grailsApp.getConfig() >> config + def resolver = new GrailsExceptionResolver() + resolver.grailsApplication = grailsApp + + and: "An exception with a mix of internal (filterable) and application frames" + def exception = new RuntimeException('boom') + exception.stackTrace = [ + new StackTraceElement('java.lang.reflect.Method', 'invoke', 'Method.java', 580), + new StackTraceElement('com.example.MyController', 'show', 'MyController.groovy', 10), + ] as StackTraceElement[] + def request = new MockHttpServletRequest('GET', '/test') + + when: "The real resolveException ordering runs: log full trace, filter, then log with request context" + resolver.logFullStackTraceIfEnabled(exception) + resolver.filterStackTrace(exception) + resolver.logStackTrace(exception, request) + + then: "Both loggers emit" + System.err.flush() + def captured = baos.toString() + captured.contains('ERROR StackTrace ') + captured.contains('Full Stack Trace:') + captured.contains('o.g.web.errors.GrailsExceptionResolver') || + captured.contains('org.grails.web.errors.GrailsExceptionResolver') + + and: "The application frame appears in both log entries" + captured.count('com.example.MyController.show(MyController.groovy:10)') == 2 + + and: "The internal frame appears only once — in the unfiltered StackTrace entry, not in the filtered resolver entry" + captured.count('java.lang.reflect.Method.invoke(Method.java:580)') == 1 + + cleanup: + System.setErr(originalErr) + } +}