fix 4x exception logging

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<StackTraceElement> newTrace = filterTraceWithCutOff(trace, cutOffPackage);
+        if (!shouldFilter) {
+            return source;
+        }
+        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);
-            }
+        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;
     }

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";
 

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}
      */

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<Throwable> filteredSources = []
+
+        CountingStackTraceFilterer() {
+            super(true)
+        }
+
+        @Override
+        Throwable filter(Throwable source) {
+            singleExceptionFilterInvocations++
+            filteredSources << source
+            super.filter(source)
+        }
     }
 }