From 919fd03f312edc37f7f74734a084fa1073a9ce8f Mon Sep 17 00:00:00 2001 From: Aditya Parikh Date: Sat, 29 Aug 2026 21:34:29 -0400 Subject: [PATCH] fix(logging): stop logback.xml from shadowing logback-spring.xml 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 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 "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) Claude-Session: https://claude.ai/code/session_01Bbs8w62uwcx12ZE8E2xg8P Signed-off-by: Aditya Parikh --- AGENTS.md | 55 ++++++++---- .../mcp/server/config/SolrNativeHints.java | 15 ++-- src/main/resources/logback-spring.xml | 67 ++++++++------- src/main/resources/logback.xml | 32 ------- .../config/LoggingConfigurationTest.java | 86 +++++++++++++++++++ .../server/config/SolrNativeHintsTest.java | 10 ++- 6 files changed, 177 insertions(+), 88 deletions(-) delete mode 100644 src/main/resources/logback.xml create mode 100644 src/test/java/org/apache/solr/mcp/server/config/LoggingConfigurationTest.java diff --git a/AGENTS.md b/AGENTS.md index 7d7ce524..bd12a414 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -132,23 +132,44 @@ artifact ships the SBOM without per-image wiring. ### Logging Architecture The STDIO transport uses stdout for JSON-RPC messages, so any stray stdout output -corrupts the protocol. Logging is configured in two layers: - -- **`logback.xml`** — Loaded by logback BEFORE Spring Boot initializes. Contains only - a `NopStatusListener` to suppress logback's internal status messages (`|-INFO`, - `|-WARN`) that would otherwise be written directly to stdout. Required for native - image where logback falls through to `BasicConfigurator` without it. -- **`logback-spring.xml`** — Loaded by Spring Boot, overrides `logback.xml`. Uses - `` blocks to scope appenders per transport mode: - - **HTTP**: CONSOLE appender (stdout) + OpenTelemetry appender (OTLP log export with - `captureExperimentalAttributes` and `captureKeyValuePairAttributes` enabled). - - **STDIO**: No appenders defined. Relies on `logging.pattern.console=` in - `application-stdio.properties` to produce empty output from Spring Boot's default - console appender. The OTEL appender is intentionally excluded to keep stdout clean. -- **`application-stdio.properties`** — Sets `logging.pattern.console=` (empty pattern) - which suppresses all Spring-managed console logging after Spring Boot initializes. - -**Init order**: logback.xml → Spring Boot starts → logback-spring.xml → application-{profile}.properties +corrupts the protocol. + +**`logback-spring.xml` is the only logging configuration this project ships, and the +`-spring` suffix is load-bearing.** Spring Boot resolves the *standard* Logback +locations (`logback-test.xml`, `logback.xml`, …) first in +`AbstractLoggingSystem.initializeWithConventions()`; if it finds one and +`logging.file.name` is unset, it reinitializes from that file and returns, never +loading the `-spring` variant. So adding a `logback.xml` alongside does not override +`logback-spring.xml` — it **disables** it, silently dropping every `` +appender. This is Boot's documented rule: `` "cannot be used in the +standard `logback.xml` file because it is loaded too early." + +That trap was live in this repo: both files existed, so HTTP mode ran with no +appenders at all — no console logs, no OTLP log export, and startup failures exited +1 showing only the Spring banner. `LoggingConfigurationTest` now fails the build if +any standard-location Logback file reappears. + +Contents of `logback-spring.xml`: + +- A `NopStatusListener` suppressing logback's internal status messages (`|-INFO`, + `|-WARN`), which are written straight to stdout and bypass the appenders. +- `` blocks scoping appenders per transport mode: + - **HTTP**: Boot's own `console-appender.xml` (so `logging.pattern.console` / + `logging.charset.console` / `logging.threshold.console` behave as in a stock Boot + app) + OpenTelemetry appender (OTLP log export with `captureExperimentalAttributes` + and `captureKeyValuePairAttributes` enabled). + - **STDIO**: No appenders defined, so nothing can reach stdout. The OTEL appender is + intentionally excluded too. +- `application-stdio.properties` additionally sets `logging.pattern.console=` (empty + pattern) as a second line of defence. + +`SolrNativeHints` registers `logback-spring.xml` as a native-image resource. + +**Init order**: Spring Boot starts → logback-spring.xml → application-{profile}.properties + +**Debugging tip**: if an HTTP-mode startup fails with no output, logging config is the +first suspect — run with `LOGGING_CONFIG=classpath:logback-spring.xml` to force-load it +and reveal the real stack trace. ### Docker image strategy diff --git a/src/main/java/org/apache/solr/mcp/server/config/SolrNativeHints.java b/src/main/java/org/apache/solr/mcp/server/config/SolrNativeHints.java index 2d1cedf8..3d9e18fd 100644 --- a/src/main/java/org/apache/solr/mcp/server/config/SolrNativeHints.java +++ b/src/main/java/org/apache/solr/mcp/server/config/SolrNativeHints.java @@ -122,12 +122,15 @@ public void registerHints(RuntimeHints hints, @Nullable ClassLoader classLoader) "org.springaicommunity.mcp.context.DefaultMetaProvider", MemberCategory.INVOKE_DECLARED_CONSTRUCTORS); - // Include logback.xml in the native image so logback's early - // initialization (before Spring Boot) finds it and applies the - // NopStatusListener. Without this, logback falls through to - // BasicConfigurator and writes status messages to stdout, - // corrupting the MCP STDIO JSON-RPC framing. - hints.resources().registerPattern("logback.xml"); + // Include logback-spring.xml in the native image so Spring Boot can + // apply the per-profile appenders (and the NopStatusListener that + // keeps stdout clean for MCP STDIO JSON-RPC framing). + // + // This must NOT be named logback.xml: Spring Boot resolves the + // standard Logback locations first and, on finding one, never loads + // the -spring variant — silently dropping every + // block. See LoggingConfigurationTest. + hints.resources().registerPattern("logback-spring.xml"); } } } diff --git a/src/main/resources/logback-spring.xml b/src/main/resources/logback-spring.xml index 0045aacc..30b44556 100644 --- a/src/main/resources/logback-spring.xml +++ b/src/main/resources/logback-spring.xml @@ -15,40 +15,51 @@ See the License for the specific language governing permissions and limitations under the License. --> + - + - - - - ${CONSOLE_LOG_PATTERN:-%d{yyyy-MM-dd HH:mm:ss.SSS} %5p --- [%15.15t] %-40.40logger{39} : %m%n} - - UTF-8 - - + + - - \ No newline at end of file + diff --git a/src/main/resources/logback.xml b/src/main/resources/logback.xml deleted file mode 100644 index 9463f026..00000000 --- a/src/main/resources/logback.xml +++ /dev/null @@ -1,32 +0,0 @@ - - - - - - diff --git a/src/test/java/org/apache/solr/mcp/server/config/LoggingConfigurationTest.java b/src/test/java/org/apache/solr/mcp/server/config/LoggingConfigurationTest.java new file mode 100644 index 00000000..eef6f98a --- /dev/null +++ b/src/test/java/org/apache/solr/mcp/server/config/LoggingConfigurationTest.java @@ -0,0 +1,86 @@ +/* + * 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 + * + * http://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.apache.solr.mcp.server.config; + +import static org.assertj.core.api.Assertions.assertThat; + +import java.net.URL; +import org.junit.jupiter.api.Test; + +/** + * Guards the logging configuration against the file-shadowing trap described in + * Spring Boot's reference documentation. + * + *

+ * Spring Boot resolves a Logback configuration in + * {@code AbstractLoggingSystem.initializeWithConventions()}. That method looks + * at the standard Logback locations first — {@code logback-test.xml}, + * {@code logback.xml} and their Groovy variants. If one is found and no + * {@code logging.file.name} is set, Boot reinitializes from that file and + * returns, so {@code logback-spring.xml} is never consulted at all. + * + *

+ * Shipping both files is therefore not "one overrides the other" — it silently + * disables the {@code -spring} file. In this application that meant the + * {@code http} profile lost its {@code CONSOLE} and {@code OTEL} appenders, + * which live in {@code logback-spring.xml} inside a {@code } + * block: HTTP mode emitted no log output whatsoever, and a failed startup + * exited 1 with nothing but the Spring banner. + * + *

+ * Boot's reference documentation states the rule directly: "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." The {@code } extension in particular + * "cannot be used in the standard logback.xml file because it is loaded too + * early". + * + * @see Spring + * Boot — Custom Log Configuration + */ +class LoggingConfigurationTest { + + private static final String[] STANDARD_LOGBACK_LOCATIONS = {"logback-test.xml", "logback-test.groovy", + "logback.groovy", "logback.xml"}; + + /** + * The {@code -spring} variant must be the configuration Spring Boot actually + * loads, which requires that no standard-location file shadows it. + */ + @Test + void springVariantIsNotShadowedByAStandardLogbackConfiguration() { + ClassLoader classLoader = getClass().getClassLoader(); + + for (String location : STANDARD_LOGBACK_LOCATIONS) { + URL shadowing = classLoader.getResource(location); + assertThat(shadowing) + .as("%s is on the classpath and shadows logback-spring.xml: Spring Boot resolves it first " + + "in AbstractLoggingSystem.initializeWithConventions() and never loads the -spring " + + "variant, so every appender is silently dropped", location) + .isNull(); + } + } + + /** The configuration Spring Boot is expected to load must exist. */ + @Test + void springVariantIsPresentOnTheClasspath() { + assertThat(getClass().getClassLoader().getResource("logback-spring.xml")) + .as("logback-spring.xml carries the per-profile appenders and must ship on the classpath").isNotNull(); + } +} diff --git a/src/test/java/org/apache/solr/mcp/server/config/SolrNativeHintsTest.java b/src/test/java/org/apache/solr/mcp/server/config/SolrNativeHintsTest.java index 3e12d098..dcbf6414 100644 --- a/src/test/java/org/apache/solr/mcp/server/config/SolrNativeHintsTest.java +++ b/src/test/java/org/apache/solr/mcp/server/config/SolrNativeHintsTest.java @@ -71,9 +71,11 @@ void registersMcpResponseRecordHints() { } @Test - void registersLogbackXmlResourceHint() { - // Required so logback's pre-Spring initialization finds logback.xml and - // stays silent on stdout (MCP STDIO framing). - assertTrue(RuntimeHintsPredicates.resource().forResource("logback.xml").test(hints)); + void registersLogbackSpringXmlResourceHint() { + // logback-spring.xml is the only logging configuration we ship: a + // standard-location logback.xml would shadow it entirely (see + // LoggingConfigurationTest). It must be reachable in the native image so + // the per-profile appenders survive AOT. + assertTrue(RuntimeHintsPredicates.resource().forResource("logback-spring.xml").test(hints)); } }