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 a3c307a329b..7bc7a985ac8 100644 --- a/grails-core/src/main/groovy/grails/config/Settings.groovy +++ b/grails-core/src/main/groovy/grails/config/Settings.groovy @@ -292,6 +292,30 @@ 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' + /** + * Whether the exception resolver should append the current auditor (resolved via a + * registered {@code org.grails.datastore.gorm.timestamp.AuditorAware} bean) to the + * exception log line. Defaults to {@code true}; set to {@code false} to keep user + * identifiers out of exception logs. When no {@code AuditorAware} bean is registered + * the log line is unchanged regardless of this setting. + */ + String SETTING_LOG_AUDITOR = 'grails.exceptionresolver.logAuditor' + /** + * Whether the exception resolver should append the remote client address + * ({@link jakarta.servlet.http.HttpServletRequest#getRemoteAddr()}) to the exception + * log line. Defaults to {@code false}; set to {@code true} to include client addresses + * in exception logs. Behind a reverse proxy, configure the servlet container + * (for example Spring Boot's {@code server.forward-headers-strategy}) so that + * {@code remoteAddr} reflects the real client IP. + */ + String SETTING_LOG_REMOTE_ADDR = 'grails.exceptionresolver.logRemoteAddr' /** * 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-datamapping-support/src/test/groovy/org/grails/datastore/mapping/core/grailsversion/GrailsVersionSpec.groovy b/grails-datamapping-support/src/test/groovy/org/grails/datastore/mapping/core/grailsversion/GrailsVersionSpec.groovy index 84eb2716ceb..05deff071f7 100644 --- a/grails-datamapping-support/src/test/groovy/org/grails/datastore/mapping/core/grailsversion/GrailsVersionSpec.groovy +++ b/grails-datamapping-support/src/test/groovy/org/grails/datastore/mapping/core/grailsversion/GrailsVersionSpec.groovy @@ -137,4 +137,4 @@ class GrailsVersionSpec extends Specification { thrown(IllegalArgumentException) } -} \ No newline at end of file +} 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..9c93cfc01fc --- /dev/null +++ b/grails-doc/src/en/guide/conf/config/logging/loggingFullStackTraces.adoc @@ -0,0 +1,163 @@ +//// +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. + +==== Including Per-Request Context in the Exception Log + +The resolver can append a small parenthesised clause of per-request context — the current user and the remote +client address — to the exception headline: + +---- +RuntimeException occurred when processing request: [GET] /admin/users/42 (ip: 198.51.100.42, user: alice) +Stacktrace follows: +---- + +When both pieces of context apply they share a single clause (`(ip: …, user: …)`); when only one applies the +clause collapses to that one entry. When neither applies, the headline is unchanged. + +===== Current User + +When the application has registered an `AuditorAware` bean (see the GORM audit timestamps section), the resolver +calls `getCurrentAuditor()` on that bean and includes ` user: ` in the clause, reusing the same auditor +resolution that populates `@CreatedBy` and `@LastModifiedBy` fields. This avoids registering a second "current +user" bean purely for logging. + +The appended value is the `toString()` of whatever the `AuditorAware` implementation returns — typically a +username string or a numeric id, depending on the type parameter chosen for the bean. If no `AuditorAware` bean +is registered, or if it returns `Optional.empty()` for the current request (for example, an unauthenticated +request), no `user:` entry is emitted. + +Enabled by default. To keep user identifiers out of exception logs — for example to satisfy a PII separation +policy, or because downstream alerting keys off the legacy headline format — set: + +[source, yaml] +.grails-app/conf/application.yml +---- +grails: + exceptionresolver: + logAuditor: false +---- + +===== Remote Client Address + +The resolver can also include the remote client address (`HttpServletRequest.getRemoteAddr()`) as ` ip: ` +in the clause. Disabled by default to avoid writing client IPs into exception logs without an explicit decision. +To opt in, set: + +[source, yaml] +.grails-app/conf/application.yml +---- +grails: + exceptionresolver: + logRemoteAddr: true +---- + +When the application is behind a reverse proxy, `getRemoteAddr()` returns the proxy's address, not the real +client's. To see the real client IP in the log, configure the servlet container to honour forwarded headers — +for Spring Boot embedded Tomcat, set `server.forward-headers-strategy: native` in `application.yml`: + +[source, yaml] +.grails-app/conf/application.yml +---- +server: + forward-headers-strategy: native +---- + +With that in place, Tomcat's `RemoteIpValve` populates `remoteAddr` from the `X-Forwarded-For` header before +the resolver reads it. The valve only honours the header when the immediate peer is in its trusted-proxy list +(loopback and RFC 1918 ranges by default; configurable via `server.tomcat.remoteip.internal-proxies`), so +spoofed headers on direct requests are ignored. + +====== Custom Address Resolution + +Applications that need a different strategy — for example, reading `X-Forwarded-For` without container-level +forwarded-header handling — can override `GrailsExceptionResolver.resolveRemoteAddr(HttpServletRequest)` in a +subclass and register that subclass as the active resolver bean. The override receives the raw request and +returns a string that is appended verbatim as `ip: `; returning `null` or an empty string omits the +entry. Be aware that any strategy which trusts request headers without a proxy-trust check is open to header +spoofing by clients that connect directly to the server. 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-doc/src/en/guide/upgrading/upgrading71x.adoc b/grails-doc/src/en/guide/upgrading/upgrading71x.adoc index 5e7817c4701..26045e73752 100644 --- a/grails-doc/src/en/guide/upgrading/upgrading71x.adoc +++ b/grails-doc/src/en/guide/upgrading/upgrading71x.adoc @@ -793,3 +793,35 @@ grails: ---- See the {gspTagsRef}flashMessages.html[flashMessages] tag reference for full details. + +===== 2.12 Exception Log Line Includes Per-Request Context + +`GrailsExceptionResolver` now appends a parenthesised clause of per-request context — the current auditor and, +optionally, the remote client address — to its exception log headline: + +---- +RuntimeException occurred when processing request: [GET] /admin/users/42 (ip: 198.51.100.42, user: alice) +---- + +The auditor entry reuses the same `AuditorAware` resolution that populates `@CreatedBy` / `@LastModifiedBy` +(see section 2.4), so no second "current user" bean is needed. The IP entry is +`HttpServletRequest.getRemoteAddr()` — behind a reverse proxy, set `server.forward-headers-strategy: native` so +the address reflects the real client. + +====== Impact + +Any log parser, alert rule, or log-aggregation query that matches on the exact exception headline format will +need to tolerate the optional ` (ip: , user: )` suffix. Auditor logging is enabled by default +when an `AuditorAware` bean is registered; remote-address logging is opt-in. Toggle each independently: + +[source, yaml] +.grails-app/conf/application.yml +---- +grails: + exceptionresolver: + logAuditor: false # drop ' user: ' + logRemoteAddr: true # add ' ip: ' +---- + +When neither applies to a given request — no `AuditorAware` bean registered and the IP suffix not enabled — the +headline collapses to its pre-7.1 form. See the Logging Full Stack Traces section of the user guide for details. diff --git a/grails-web-mvc/src/main/groovy/org/grails/web/errors/AuditorAwareLookup.java b/grails-web-mvc/src/main/groovy/org/grails/web/errors/AuditorAwareLookup.java new file mode 100644 index 00000000000..29b8a15c8c3 --- /dev/null +++ b/grails-web-mvc/src/main/groovy/org/grails/web/errors/AuditorAwareLookup.java @@ -0,0 +1,101 @@ +/* + * 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. + */ +package org.grails.web.errors; + +import java.lang.reflect.Method; +import java.util.Optional; + +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +import org.springframework.beans.BeansException; +import org.springframework.context.ApplicationContext; +import org.springframework.util.ClassUtils; + +/** + * Optional integration with the GORM {@code AuditorAware} bean. When the audit API + * class is on the classpath and a bean is registered, {@link #getCurrentAuditor()} + * returns its result so the exception resolver can reuse the same "current user" + * resolution that {@code @CreatedBy} uses. The lookup is reflective so that this + * module does not compile-time depend on {@code grails-datamapping-core}. + * + *

Any failure — missing class, missing bean, invocation error — resolves to an + * empty {@code Optional}. Exception logging must never be blocked by a broken + * auditor lookup.

+ */ +class AuditorAwareLookup { + + private static final Logger LOG = LoggerFactory.getLogger(AuditorAwareLookup.class); + private static final String AUDITOR_AWARE_CLASS = "org.grails.datastore.gorm.timestamp.AuditorAware"; + + private final ApplicationContext applicationContext; + + private volatile boolean resolved; + private Object bean; + private Method getCurrentAuditor; + + AuditorAwareLookup(ApplicationContext applicationContext) { + this.applicationContext = applicationContext; + } + + Optional getCurrentAuditor() { + if (!resolve() || bean == null) { + return Optional.empty(); + } + try { + Object result = getCurrentAuditor.invoke(bean); + return result instanceof Optional ? (Optional) result : Optional.empty(); + } + catch (ReflectiveOperationException e) { + LOG.debug("AuditorAware#getCurrentAuditor invocation failed", e); + return Optional.empty(); + } + } + + private boolean resolve() { + if (resolved) { + return true; + } + synchronized (this) { + if (resolved) { + return true; + } + try { + if (applicationContext != null && + ClassUtils.isPresent(AUDITOR_AWARE_CLASS, applicationContext.getClassLoader())) { + Class type = ClassUtils.forName(AUDITOR_AWARE_CLASS, applicationContext.getClassLoader()); + try { + bean = applicationContext.getBean(type); + getCurrentAuditor = type.getMethod("getCurrentAuditor"); + } + catch (BeansException noBean) { + // optional — no bean registered + } + } + } + catch (Throwable t) { + LOG.debug("AuditorAware integration unavailable", t); + } + finally { + resolved = true; + } + } + return true; + } +} 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..41697da4e0a 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 @@ -19,6 +19,7 @@ package org.grails.web.errors; import java.io.IOException; +import java.util.ArrayList; import java.util.Collections; import java.util.Enumeration; import java.util.HashMap; @@ -77,6 +78,7 @@ public class GrailsExceptionResolver extends SimpleMappingExceptionResolver impl protected ServletContext servletContext; protected GrailsApplication grailsApplication; protected StackTraceFilterer stackFilterer; + protected AuditorAwareLookup auditorAwareLookup; /* (non-Javadoc) * @see org.springframework.web.servlet.handler.SimpleMappingExceptionResolver#resolveException(jakarta.servlet.http.HttpServletRequest, jakarta.servlet.http.HttpServletResponse, java.lang.Object, java.lang.Exception) @@ -89,6 +91,8 @@ public ModelAndView resolveException(HttpServletRequest request, HttpServletResp ex = findWrappedException(ex); + logFullStackTraceIfEnabled(ex); + filterStackTrace(ex); ModelAndView mv = super.resolveException(request, response, handler, ex); @@ -123,6 +127,7 @@ public void setServletContext(ServletContext servletContext) { public void setGrailsApplication(GrailsApplication grailsApplication) { this.grailsApplication = grailsApplication; createStackFilterer(); + this.auditorAwareLookup = new AuditorAwareLookup(grailsApplication.getMainContext()); } /** @@ -261,6 +266,70 @@ 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 boolean shouldLogAuditor() { + Config config = grailsApplication != null ? grailsApplication.getConfig() : null; + return config != null && config.getProperty(Settings.SETTING_LOG_AUDITOR, Boolean.class, true); + } + + protected boolean shouldLogRemoteAddr() { + Config config = grailsApplication != null ? grailsApplication.getConfig() : null; + return config != null && config.getProperty(Settings.SETTING_LOG_REMOTE_ADDR, Boolean.class, false); + } + + /** + * Resolves the client address to include in the exception log headline. The default + * returns {@link HttpServletRequest#getRemoteAddr()} — the container's view of the + * TCP peer, which reflects forwarded-header handling only when the servlet container + * is configured to trust a proxy chain (for example Spring Boot's + * {@code server.forward-headers-strategy}). Subclasses can override this to apply a + * different resolution strategy; the returned value (null or empty to omit) is + * appended verbatim as {@code ip: }. + */ + protected String resolveRemoteAddr(HttpServletRequest request) { + return request.getRemoteAddr(); + } + + /** + * Appends optional per-request context (remote address, current auditor) to the log + * headline as a single parenthesised clause — e.g. {@code (ip: 1.2.3.4, user: alice)}. + * Emits nothing when no tokens apply, so the baseline headline format is unchanged. + */ + protected void appendRequestContext(StringBuilder sb, HttpServletRequest request) { + List tokens = new ArrayList<>(2); + if (shouldLogRemoteAddr()) { + String remoteAddr = resolveRemoteAddr(request); + if (remoteAddr != null && !remoteAddr.isEmpty()) { + tokens.add("ip: " + remoteAddr); + } + } + if (shouldLogAuditor() && auditorAwareLookup != null) { + auditorAwareLookup.getCurrentAuditor().ifPresent(auditor -> + tokens.add("user: " + auditor) + ); + } + if (!tokens.isEmpty()) { + sb.append(" (").append(String.join(", ", tokens)).append(")"); + } + } + protected Exception findWrappedException(Exception e) { if ((e instanceof InvokerInvocationException) || (e instanceof GrailsMVCException)) { Throwable t = getRootCause(e); @@ -284,6 +353,8 @@ protected String getRequestLogMessage(String exceptionName, HttpServletRequest r sb.append(request.getRequestURI()); } + appendRequestContext(sb, request); + Config config = grailsApplication != null ? grailsApplication.getConfig() : null; final boolean shouldLogRequestParameters = config != null ? config.getProperty(Settings.SETTING_LOG_REQUEST_PARAMETERS, Boolean.class, Environment.getCurrent() == Environment.DEVELOPMENT) : false; 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..6bdce69ac7c 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,248 @@ 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 "getRequestLogMessage appends auditor when logAuditor is enabled and the lookup returns a value"() { + given: + def config = Mock(Config) + config.getProperty('grails.exceptionresolver.logAuditor', Boolean, true) >> true + config.getProperty('grails.exceptionresolver.logRemoteAddr', Boolean, false) >> false + config.getProperty('grails.exceptionresolver.logRequestParameters', Boolean, _) >> false + def grailsApp = Mock(GrailsApplication) + grailsApp.getConfig() >> config + def resolver = new GrailsExceptionResolver() + resolver.grailsApplication = grailsApp + resolver.auditorAwareLookup = new AuditorAwareLookup(null) { + @Override + Optional getCurrentAuditor() { Optional.of('alice') } + } + def request = new MockHttpServletRequest('GET', '/test') + + when: + def msg = resolver.getRequestLogMessage('RuntimeException', request, 'boom') + + then: + msg.contains('(user: alice)') + } + + void "getRequestLogMessage omits auditor when logAuditor is disabled"() { + given: + def config = Mock(Config) + config.getProperty('grails.exceptionresolver.logAuditor', Boolean, true) >> false + config.getProperty('grails.exceptionresolver.logRemoteAddr', Boolean, false) >> false + config.getProperty('grails.exceptionresolver.logRequestParameters', Boolean, _) >> false + def grailsApp = Mock(GrailsApplication) + grailsApp.getConfig() >> config + def resolver = new GrailsExceptionResolver() + resolver.grailsApplication = grailsApp + resolver.auditorAwareLookup = new AuditorAwareLookup(null) { + @Override + Optional getCurrentAuditor() { Optional.of('alice') } + } + def request = new MockHttpServletRequest('GET', '/test') + + when: + def msg = resolver.getRequestLogMessage('RuntimeException', request, 'boom') + + then: + !msg.contains('(user:') + } + + void "getRequestLogMessage omits auditor when logAuditor is enabled but auditor is absent"() { + given: + def config = Mock(Config) + config.getProperty('grails.exceptionresolver.logAuditor', Boolean, true) >> true + config.getProperty('grails.exceptionresolver.logRemoteAddr', Boolean, false) >> false + config.getProperty('grails.exceptionresolver.logRequestParameters', Boolean, _) >> false + def grailsApp = Mock(GrailsApplication) + grailsApp.getConfig() >> config + def resolver = new GrailsExceptionResolver() + resolver.grailsApplication = grailsApp + resolver.auditorAwareLookup = new AuditorAwareLookup(null) { + @Override + Optional getCurrentAuditor() { Optional.empty() } + } + def request = new MockHttpServletRequest('GET', '/test') + + when: + def msg = resolver.getRequestLogMessage('RuntimeException', request, 'boom') + + then: + !msg.contains('(user:') + } + + void "getRequestLogMessage appends remote address when logRemoteAddr is enabled"() { + given: + def config = Mock(Config) + config.getProperty('grails.exceptionresolver.logAuditor', Boolean, true) >> false + config.getProperty('grails.exceptionresolver.logRemoteAddr', Boolean, false) >> true + config.getProperty('grails.exceptionresolver.logRequestParameters', Boolean, _) >> false + def grailsApp = Mock(GrailsApplication) + grailsApp.getConfig() >> config + def resolver = new GrailsExceptionResolver() + resolver.grailsApplication = grailsApp + def request = new MockHttpServletRequest('GET', '/test') + request.remoteAddr = '198.51.100.42' + + when: + def msg = resolver.getRequestLogMessage('RuntimeException', request, 'boom') + + then: + msg.contains('(ip: 198.51.100.42)') + !msg.contains('user:') + } + + void "getRequestLogMessage combines remote address and auditor into a single clause when both are enabled"() { + given: + def config = Mock(Config) + config.getProperty('grails.exceptionresolver.logAuditor', Boolean, true) >> true + config.getProperty('grails.exceptionresolver.logRemoteAddr', Boolean, false) >> true + config.getProperty('grails.exceptionresolver.logRequestParameters', Boolean, _) >> false + def grailsApp = Mock(GrailsApplication) + grailsApp.getConfig() >> config + def resolver = new GrailsExceptionResolver() + resolver.grailsApplication = grailsApp + resolver.auditorAwareLookup = new AuditorAwareLookup(null) { + @Override + Optional getCurrentAuditor() { Optional.of(42L) } + } + def request = new MockHttpServletRequest('GET', '/test') + request.remoteAddr = '198.51.100.42' + + when: + def msg = resolver.getRequestLogMessage('RuntimeException', request, 'boom') + + then: + msg.contains('(ip: 198.51.100.42, user: 42)') + } + + void "subclasses can override resolveRemoteAddr to supply a custom IP extraction"() { + given: + def config = Mock(Config) + config.getProperty('grails.exceptionresolver.logAuditor', Boolean, true) >> false + config.getProperty('grails.exceptionresolver.logRemoteAddr', Boolean, false) >> true + config.getProperty('grails.exceptionresolver.logRequestParameters', Boolean, _) >> false + def grailsApp = Mock(GrailsApplication) + grailsApp.getConfig() >> config + def resolver = new GrailsExceptionResolver() { + @Override + protected String resolveRemoteAddr(HttpServletRequest req) { + req.getHeader('X-Forwarded-For') ?: req.remoteAddr + } + } + resolver.grailsApplication = grailsApp + def request = new MockHttpServletRequest('GET', '/test') + request.remoteAddr = '10.0.0.1' + request.addHeader('X-Forwarded-For', '203.0.113.7') + + when: + def msg = resolver.getRequestLogMessage('RuntimeException', request, 'boom') + + then: + msg.contains('(ip: 203.0.113.7)') + } + + void "AuditorAwareLookup returns empty when no application context is provided"() { + given: + def lookup = new AuditorAwareLookup(null) + + expect: + !lookup.getCurrentAuditor().isPresent() + } + + 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.logAuditor', Boolean, true) >> false + config.getProperty('grails.exceptionresolver.logRemoteAddr', Boolean, false) >> false + 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) + } +}