Skip to content

fix: capture STACK_LOG output via a Logback appender instead of System.err - #16067

Open
borinquenkid wants to merge 2 commits into
8.0.xfrom
fix/stacktrace-filterer-test-log-capture
Open

fix: capture STACK_LOG output via a Logback appender instead of System.err#16067
borinquenkid wants to merge 2 commits into
8.0.xfrom
fix/stacktrace-filterer-test-log-capture

Conversation

@borinquenkid

@borinquenkid borinquenkid commented Jul 29, 2026

Copy link
Copy Markdown
Member

Summary

GrailsUtilStackFiltererSpec and GrailsBootstrapRegistryInitializerSpec each have a positive-control
test asserting that DefaultStackTraceFilterer emits a Full Stack Trace: message by default. Both
originally captured that output by swapping System.err for a ByteArrayOutputStream around the call,
which stopped working once grails-core's logback-test.xml (added in d1c8d0e439) set root level="WARN" with zero appenders -- the message isn't merely misrouted, it's written nowhere at all,
so the System.err swap never observes anything regardless of timing or test ordering.

Note on scope: while this PR was in flight, #16011 independently merged its own fix for the same two
specs (commit bdb98a6636), using LogCapture('StackTrace') (string literal). Per @jamesfredley's review
below, this PR has been repurposed as the definitive cleanup for this failure mode rather than closed:

  • Rebased onto current 8.0.x; kept the STACK_LOG_NAME constant (over the string literal #16011 used)
    in the two already-fixed specs.
  • Converted the one remaining latent instance: grails-web-mvc's GrailsExceptionResolverSpec (3 sites),
    which only passed today because that module's test classpath carried slf4j-simple (whose SYS_ERR
    output choice re-reads System.err per call instead of caching it) -- the same trap that broke the
    grails-core specs once that module got a deterministic logback-test.xml. One of the three assertions
    matched the literal console layout string 'ERROR StackTrace ', which is about as brittle as it gets.
  • Swapped grails-web-mvc's test logging binding from slf4j-simple to grails-core's test fixtures
    (brings logback-classic transitively, needed since LogCapture attaches to a real Logback Logger),
    and rewrote the three specs to assert on captured ILoggingEvents -- including inspecting each event's
    throwableProxy stack frames directly instead of counting substrings in rendered console text.

No production code changes; behavior of DefaultStackTraceFilterer / GrailsExceptionResolver is
unchanged throughout.

Test plan

  • :grails-core:test --tests grails.util.GrailsUtilStackFiltererSpec --tests org.apache.grails.core.GrailsBootstrapRegistryInitializerSpec --tests org.grails.exception.reporting.StackTraceFiltererSpec -- all pass
  • :grails-web-mvc:test --tests org.grails.web.errors.GrailsExceptionResolverSpec (and full module) -- all pass
  • :grails-core:codeStyle, :grails-web-mvc:codeStyle -- pass

🤖 Generated with Claude Code

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

This PR fixes two failing grails-core specs by capturing DefaultStackTraceFilterer’s Full Stack Trace: output via the actual logging pipeline (SLF4J/Logback) instead of attempting to capture System.err, which no longer observes that output when commons-logging is bridged to SLF4J.

Changes:

  • Replace System.err swapping in two specs with a Logback ListAppender attached to DefaultStackTraceFilterer.STACK_LOG_NAME (StackTrace).
  • Add small attach/detach helpers and assertions that inspect captured ILoggingEvents for StackTraceFilterer.FULL_STACK_TRACE_MESSAGE.

Reviewed changes

Copilot reviewed 2 out of 2 changed files in this pull request and generated 2 comments.

File Description
grails-core/src/test/groovy/org/apache/grails/core/GrailsBootstrapRegistryInitializerSpec.groovy Switches the “logFullStackTraceOnFilter” default/override assertions from System.err capture to a Logback ListAppender on the StackTrace logger.
grails-core/src/test/groovy/grails/util/GrailsUtilStackFiltererSpec.groovy Switches the DefaultStackTraceFilterer positive/negative control assertions from System.err capture to a Logback ListAppender on the StackTrace logger.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Comment thread grails-core/src/test/groovy/grails/util/GrailsUtilStackFiltererSpec.groovy Outdated
borinquenkid added a commit that referenced this pull request Jul 29, 2026
Address Copilot review on #16067: grails-core already has
org.apache.grails.core.testing.support.LogCapture for exactly this purpose
(used by StackTraceFiltererSpec), which also restores logger level and
additivity on close. Drop the duplicated attach/detach helpers in favor of it.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
@borinquenkid
borinquenkid requested a review from jdaugherty July 29, 2026 22:40
@jamesfredley

Copy link
Copy Markdown
Contributor

Heads up - #16011 was merged (301b40c20a), and it carried its own fix for these same two specs, so this PR is now CONFLICTING against 8.0.x.

On 8.0.x today, GrailsUtilStackFiltererSpec and GrailsBootstrapRegistryInitializerSpec already capture via the shared LogCapture test fixture (grails-core/src/testFixtures/groovy/org/apache/grails/core/testing/support/LogCapture.groovy) rather than the inline attachRecordingAppender() / detachAppender() helpers proposed here. Both approaches were correct; LogCapture won on the tiebreak that it already existed and is already the house pattern (StackTraceFiltererSpec, DefaultGrailsPluginManagerSpec, PluginDiscoverySpec, GlobalGrailsClassInjectorTransformationSpec), and it additionally forces the logger to TRACE, sets additive = false, and restores both on close() - which is what makes it independent of whatever root level and appender set a given module happens to configure.

Rather than close this, I'd like to repurpose it as the definitive cleanup for this failure mode. It has now surfaced two or three separate times, and there is still a live latent instance.

1. Diagnosis is slightly off, and the correction matters

The description attributes the failure to STACK_LOG resolving to a jcl-over-slf4j binding so the message "never reaches System.err at all." That is true as far as it goes, but it is not the proximate trigger. The actual trigger is d1c8d0e439 ("test: add deterministic test logging configuration"), which added grails-core/src/test/resources/logback-test.xml:

<configuration>
    <root level="WARN" />
</configuration>

Root at WARN with zero appenders - so the event is not merely routed away from System.err, it is written nowhere at all.

The evidence that this is the real cause: GrailsExceptionResolverSpec in grails-web-mvc uses the identical System.setErr + captured.contains('Full Stack Trace:') pattern against the same STACK_LOG, and it passes today. grails-web-mvc has no src/test/resources at all, so it falls through to a default console configuration and the capture happens to work. Same binding, same logger, opposite result - the difference is purely the per-module logback test config.

2. Remaining latent instance

grails-web-mvc/src/test/groovy/org/grails/web/errors/GrailsExceptionResolverSpec.groovy still has three System.setErr capture sites (L59, L84, L270), two of which assert on StackTrace logger output including 'Full Stack Trace:' and the literal 'ERROR StackTrace ' console prefix. That last assertion is coupled to a console appender's layout pattern, which is about as brittle as it gets. It will break the same way the moment grails-web-mvc gets the same deterministic logback-test.xml treatment grails-core received.

3. Suggested scope for this PR

  1. Convert those three sites in GrailsExceptionResolverSpec to LogCapture, keyed on DefaultStackTraceFilterer.STACK_LOG_NAME and the resolver's own logger, asserting on formattedMessage / level instead of a rendered console line.
  2. Switch the two already-merged specs from the 'StackTrace' string literal to DefaultStackTraceFilterer.STACK_LOG_NAME - this PR had that right and Opt-in backwards compatibility for Grails 7 command plugins on Grails 8 #16011 did not.
  3. Once no test in the module asserts on incidental console output, roll the deterministic logback-test.xml out to grails-web-mvc (and ideally the other test modules) so this cannot regress a fourth time. That converts "it happens to pass because this module has no logging config" into "it passes because the test attaches its own appender."

Optionally, a short note in the LogCapture javadoc stating that tests must never assert on System.out/System.err for anything emitted through a logger would give reviewers something concrete to point at.

4. Re: the logging changes that just merged

#15757 (stop scaffolding logback-spring.xml, add the opt-in Forge feature) and the earlier content fixes in #15973 are app-generation scope only - they do not touch any module's test classpath, so there is no direct collision with this work. But they do reinforce the same direction: rely on the framework's default logging configuration rather than a checked-in file, and correspondingly stop writing tests that depend on what that default configuration happens to render to a stream.

Rebase note

Since the two specs already changed on 8.0.x, the cleanest path is to rebase onto current 8.0.x and drop the parts of this diff that #16011 already covers, keeping the constant-vs-literal fix, then add the grails-web-mvc conversion and the config rollout on top.

borinquenkid and others added 2 commits July 29, 2026 18:29
…m.err

DefaultStackTraceFilterer.STACK_LOG routes through commons-logging, which
resolves to a jcl-over-slf4j binding on this classpath -- so its output never
touches System.err, regardless of test ordering or timing. Swapping
System.err therefore never observes the emitted message, making
GrailsUtilStackFiltererSpec and GrailsBootstrapRegistryInitializerSpec fail
deterministically. Attach a ListAppender directly to the public STACK_LOG_NAME
logger instead, which is unaffected by which commons-logging backend wins the
classpath.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
…ystem.err capture

Address jamesfredley's review on #16067: this was the one remaining latent
instance of the same fragility -- three sites asserting on rendered
System.err output for the STACK_LOG and GrailsExceptionResolver loggers,
including one match on the literal console layout string 'ERROR StackTrace '.
It passed only because grails-web-mvc's test classpath happened to carry
slf4j-simple, whose SYS_ERR output choice re-reads System.err per call rather
than caching it -- the same trap that broke these tests in grails-core once
that module got a deterministic logback-test.xml.

Swap the module's test logging binding from slf4j-simple to grails-core's
test fixtures (which bring logback-classic transitively), and rewrite the
three specs to assert on captured ILoggingEvents instead of console text --
including inspecting each event's throwableProxy stack frames directly
rather than counting substrings in rendered output.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
@borinquenkid
borinquenkid force-pushed the fix/stacktrace-filterer-test-log-capture branch from 5ec758d to a8227fd Compare July 29, 2026 23:39
@borinquenkid

Copy link
Copy Markdown
Member Author

Thanks for the correction and for pushing this further -- addressed all three points:

1. Diagnosis corrected -- updated the PR description to point at the actual trigger (grails-core's logback-test.xml shipping root level=\"WARN\" with zero appenders, so the event goes nowhere, not merely "routed away from System.err"). Good catch on GrailsExceptionResolverSpec being the control case that proves it.

2. Rebased onto current 8.0.x past #16011's merge. Kept STACK_LOG_NAME over the string literal in the two already-landed specs.

3. GrailsExceptionResolverSpec converted -- all three System.setErr sites now use LogCapture (one keyed on GrailsExceptionResolver, one on DefaultStackTraceFilterer.STACK_LOG_NAME). The combined test that used to count substrings in rendered console output (including the brittle 'ERROR StackTrace ' layout match) now inspects each captured ILoggingEvent's throwableProxy stack frames directly. This required swapping the module's test logging binding from slf4j-simple to grails-core's test fixtures (transitively brings logback-classic, which LogCapture needs to attach a real Logback Logger) -- verified no other test in the module depended on slf4j-simple specifically.

Held off on rolling the deterministic logback-test.xml out to grails-web-mvc itself (your point 3) -- LogCapture forces the target logger's own level to TRACE and attaches its own appender directly, so the module's tests are now independent of root logger config either way, and adding that file felt like a separate, broader change (affects visible output for every test in the module, not just these). Happy to do it here too if you'd rather bundle it.

@testlens-app

testlens-app Bot commented Jul 30, 2026

Copy link
Copy Markdown

✅ All tests passed ✅

🏷️ Commit: a8227fd
▶️ Tests: 49409 executed
⚪️ Checks: 60/60 completed


Learn more about TestLens at testlens.app.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

Status: No status

Development

Successfully merging this pull request may close these issues.

3 participants