Skip to content

fix(logging): stop logback.xml from shadowing logback-spring.xml - #189

Open
adityamparikh wants to merge 1 commit into
apache:mainfrom
adityamparikh:fix/logback-spring-config-never-loaded
Open

fix(logging): stop logback.xml from shadowing logback-spring.xml#189
adityamparikh wants to merge 1 commit into
apache:mainfrom
adityamparikh:fix/logback-spring-config-never-loaded

Conversation

@adityamparikh

@adityamparikh adityamparikh commented Aug 30, 2026

Copy link
Copy Markdown
Contributor

The bug

logback-spring.xml is never loaded. HTTP mode therefore runs with no appenders at all — no console logging and no OTLP log export — and any startup failure exits 1 printing nothing but the Spring banner.

Reproduce on main:

PROFILES=http ./gradlew bootRun

Output is the banner, four JVM Unsafe warnings, then:

> Task :bootRun FAILED
> Process 'command '.../bin/java'' finished with non-zero exit value 1

No stack trace, no failure analyzer, no APPLICATION FAILED TO START. Force the config and the real error appears:

LOGGING_CONFIG=classpath:logback-spring.xml PROFILES=http ./gradlew bootRun
# 0 log lines before -> 34 after, including:
#   The following 1 profile is active: "http"

Root cause

Spring Boot's AbstractLoggingSystem.initializeWithConventions() checks the standard Logback locations first (logback-test.xml, logback.xml, …). If it finds one and logging.file.name is unset, it calls reinitialize() and returns earlylogback-spring.xml is never consulted.

This repo shipped both files. logback.xml contains only a NopStatusListener and no appenders, so it won a race it was never meant to enter, and the <springProfile> blocks holding CONSOLE and OTEL silently disappeared.

LoggerFactory first touch
  └─► logback auto-config picks logback.xml   (statusListener only, no appenders)

Spring Boot ApplicationEnvironmentPreparedEvent
  └─► AbstractLoggingSystem.initializeWithConventions()
        ├─ getSelfInitializationConfig() -> logback.xml FOUND
        ├─ reinitialize()   <-- reloads logback.xml
        └─ return           <-- logback-spring.xml never loaded
                                 CONSOLE + OTEL never exist

This is Boot's documented rule, not an edge case:

We recommend that you use the -spring variant for your logging configuration (for example, logback-spring.xml rather than logback.xml). If you use standard configuration locations, Spring cannot completely control log initialization.

[Logback extensions] cannot be used in the standard logback.xml file because it is loaded too early.

The fix

Delete logback.xml; logback-spring.xml becomes the single logging configuration. The NopStatusListener was already declared in logback-spring.xml, so deleting the other file activates the suppression rather than removing it.

Also in this PR:

  • Use Boot's own console-appender.xml instead of a hand-rolled ConsoleAppender, so logging.pattern.console / logging.charset.console / logging.threshold.console behave as in a stock Boot app. The hand-rolled encoder's fallback was already dead code: defaults.xml defines CONSOLE_LOG_PATTERN, so ${CONSOLE_LOG_PATTERN:-…} always resolved to Boot's pattern — the rendered format is unchanged.
  • Register logback-spring.xml (not logback.xml) as a native-image resource in SolrNativeHints.
  • Add LoggingConfigurationTest, which fails the build if any standard-location Logback file reappears.
  • Correct the Logging Architecture section of AGENTS.md, which claimed "logback-spring.xml — Loaded by Spring Boot, overrides logback.xml." That was the intent, not the behaviour.

Why removing logback.xml is safe for STDIO

logback.xml was justified as "Required for native image where logback falls through to BasicConfigurator." The STDIO transport's stdout cleanliness is directly covered by McpClientStdioIntegrationTest, which spawns the real java -jar and runs the full MCP JSON-RPC workflow — a single stray stdout line fails it.

Verification

Check Result
./gradlew build ✅ 391 tests, 0 failures, 7 skipped
McpClientStdioIntegrationTest (real jar, MCP over stdout) ✅ 39/39, 0 skipped
LoggingConfigurationTest ✅ 2/2 (fails on main)
PROFILES=http ./gradlew bootRun, no override ✅ 34 log lines (0 before)
./gradlew nativeTest -Pnative 244 passed, 0 failed, 144 skipped (BUILD SUCCESSFUL, 6m24s)

The native run is a meaningful check here, not a formality: in a native image getResource only sees registered resources, so LoggingConfigurationTest passing there confirms the hint swap actually took effect in the closed world — logback.xml is absent and logback-spring.xml is reachable. Both of its tests ran natively (not skipped).

For reference, the 144 skips are 142 pre-existing plus the two @DisabledInNativeImage ApplicationContextRunner tests that arrive with an unrelated branch in my local tree; they are not part of this PR.

🤖 Generated with Claude Code

https://claude.ai/code/session_01Bbs8w62uwcx12ZE8E2xg8P

Spring Boot resolves the standard Logback locations (logback-test.xml,
logback.xml, ...) first in AbstractLoggingSystem.initializeWithConventions().
When one is found and logging.file.name is unset, Boot reinitializes from that
file and returns, so logback-spring.xml is never loaded at all.

This project shipped both files, so the <springProfile> blocks in
logback-spring.xml -- which hold the only appenders -- never took effect. HTTP
mode ran with no appenders whatsoever: no console logging and no OTLP log
export. A failed startup then exited 1 printing nothing but the Spring banner,
leaving Gradle to report only "finished with non-zero exit value 1", which
makes any HTTP-mode startup failure effectively undiagnosable.

Delete logback.xml and keep logback-spring.xml as the single logging
configuration. This is what Boot's reference documentation recommends: use the
-spring variant "to allow Spring to fully control log initialization", and
<springProfile> "cannot be used in the standard logback.xml file because it is
loaded too early". The NopStatusListener that logback.xml carried is already
declared in logback-spring.xml, so removing the file activates that
suppression rather than dropping it.

Also in this change:

* Use Boot's own console-appender.xml instead of a hand-rolled ConsoleAppender,
  so logging.pattern.console, logging.charset.console and
  logging.threshold.console behave as they do in a stock Boot application. The
  hand-rolled encoder's fallback was already dead code -- defaults.xml defines
  CONSOLE_LOG_PATTERN, so ${CONSOLE_LOG_PATTERN:-...} always resolved to Boot's
  pattern.
* Register logback-spring.xml, not logback.xml, as a native-image resource.
* Add LoggingConfigurationTest, which fails the build if any standard-location
  Logback file reappears and re-triggers the shadowing.
* Correct the Logging Architecture section of AGENTS.md, which described
  logback-spring.xml as overriding logback.xml -- the intent, not the
  behaviour.

Verified: PROFILES=http ./gradlew bootRun emits log output with no
LOGGING_CONFIG override (0 lines before this change, 34 after). STDIO stdout
cleanliness is covered by McpClientStdioIntegrationTest, which drives the MCP
JSON-RPC workflow over the real jar's stdout; it passes 39/39, and the full
./gradlew build is green at 391 tests, 0 failures.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Bbs8w62uwcx12ZE8E2xg8P
Signed-off-by: Aditya Parikh <aditya.m.parikh@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant