From c256f41fce1c97296a231f5f30fc0ab3f9881c08 Mon Sep 17 00:00:00 2001 From: Dmytro Nosan Date: Thu, 19 Dec 2024 14:40:56 +0200 Subject: [PATCH 1/2] Logback StructuredLogFormatter exceptions are not visible to the user Before this commit, any exceptions thrown in Logback encoders were just swallowed. This commit adds the FilteringStatusListener that delegates to OnErrorConsoleStatusListener to print any errors that happened in logback encoders. See gh-43575 Signed-off-by: Dmytro Nosan --- .../logback/FilteringStatusListener.java | 80 ++++++++++++ .../logging/logback/LogbackLoggingSystem.java | 12 ++ .../logback/FilteringStatusListenerTests.java | 121 ++++++++++++++++++ .../logback/LogbackLoggingSystemTests.java | 37 +++++- .../DuplicateJsonMembersCustomizer.java | 32 +++++ .../src/main/resources/application.properties | 3 + ...mpleStructuredLoggingApplicationTests.java | 8 +- 7 files changed, 291 insertions(+), 2 deletions(-) create mode 100644 spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/FilteringStatusListener.java create mode 100644 spring-boot-project/spring-boot/src/test/java/org/springframework/boot/logging/logback/FilteringStatusListenerTests.java create mode 100644 spring-boot-tests/spring-boot-smoke-tests/spring-boot-smoke-test-structured-logging/src/main/java/smoketest/structuredlogging/DuplicateJsonMembersCustomizer.java diff --git a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/FilteringStatusListener.java b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/FilteringStatusListener.java new file mode 100644 index 000000000000..b2625044a646 --- /dev/null +++ b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/FilteringStatusListener.java @@ -0,0 +1,80 @@ +/* + * Copyright 2012-2025 the original author or authors. + * + * Licensed 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.springframework.boot.logging.logback; + +import ch.qos.logback.core.spi.ContextAwareBase; +import ch.qos.logback.core.spi.LifeCycle; +import ch.qos.logback.core.status.Status; +import ch.qos.logback.core.status.StatusListener; + +/** + * Logback {@link StatusListener} that filters {@link Status} by its logging level and + * delegates to the underlying {@code StatusListener}. + * + * @author Dmytro Nosan + */ +final class FilteringStatusListener extends ContextAwareBase implements StatusListener, LifeCycle { + + private final StatusListener delegate; + + private final int levelThreshold; + + /** + * Creates a new {@link FilteringStatusListener}. + * @param delegate the {@link StatusListener} delegate to + * @param levelThreshold the minimum log level accepted for delegation + */ + FilteringStatusListener(StatusListener delegate, int levelThreshold) { + this.delegate = delegate; + this.levelThreshold = levelThreshold; + } + + @Override + public void addStatusEvent(Status status) { + if (status.getLevel() >= this.levelThreshold) { + this.delegate.addStatusEvent(status); + } + } + + @Override + public boolean isResetResistant() { + return this.delegate.isResetResistant(); + } + + @Override + public void start() { + if (this.delegate instanceof LifeCycle lifeCycle) { + lifeCycle.start(); + } + } + + @Override + public void stop() { + if (this.delegate instanceof LifeCycle lifeCycle) { + lifeCycle.stop(); + } + } + + @Override + public boolean isStarted() { + if (this.delegate instanceof LifeCycle lifeCycle) { + return lifeCycle.isStarted(); + } + return true; + } + +} diff --git a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/LogbackLoggingSystem.java b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/LogbackLoggingSystem.java index c5e6d891ac71..d143b37fb258 100644 --- a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/LogbackLoggingSystem.java +++ b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/LogbackLoggingSystem.java @@ -36,6 +36,7 @@ import ch.qos.logback.core.joran.spi.JoranException; import ch.qos.logback.core.spi.FilterReply; import ch.qos.logback.core.status.OnConsoleStatusListener; +import ch.qos.logback.core.status.OnErrorConsoleStatusListener; import ch.qos.logback.core.status.Status; import ch.qos.logback.core.status.StatusUtil; import ch.qos.logback.core.util.StatusListenerConfigHelper; @@ -234,6 +235,9 @@ protected void loadDefaults(LoggingInitializationContext initializationContext, if (debug) { StatusListenerConfigHelper.addOnConsoleListenerInstance(loggerContext, new OnConsoleStatusListener()); } + else { + addOnErrorConsoleStatusListener(loggerContext); + } Environment environment = initializationContext.getEnvironment(); // Apply system properties directly in case the same JVM runs multiple apps new LogbackLoggingSystemProperties(environment, getDefaultValueResolver(environment), @@ -487,6 +491,14 @@ private void withLoggingSuppressed(Runnable action) { } } + private void addOnErrorConsoleStatusListener(LoggerContext context) { + FilteringStatusListener listener = new FilteringStatusListener(new OnErrorConsoleStatusListener(), + Status.ERROR); + listener.setContext(context); + context.getStatusManager().add(listener); + listener.start(); + } + void setStatusPrinterStream(PrintStream stream) { this.statusPrinter.setPrintStream(stream); } diff --git a/spring-boot-project/spring-boot/src/test/java/org/springframework/boot/logging/logback/FilteringStatusListenerTests.java b/spring-boot-project/spring-boot/src/test/java/org/springframework/boot/logging/logback/FilteringStatusListenerTests.java new file mode 100644 index 000000000000..c2533ed39a45 --- /dev/null +++ b/spring-boot-project/spring-boot/src/test/java/org/springframework/boot/logging/logback/FilteringStatusListenerTests.java @@ -0,0 +1,121 @@ +/* + * Copyright 2012-2025 the original author or authors. + * + * Licensed 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.springframework.boot.logging.logback; + +import java.util.ArrayList; +import java.util.List; + +import ch.qos.logback.core.spi.LifeCycle; +import ch.qos.logback.core.status.ErrorStatus; +import ch.qos.logback.core.status.InfoStatus; +import ch.qos.logback.core.status.Status; +import ch.qos.logback.core.status.StatusListener; +import ch.qos.logback.core.status.WarnStatus; +import org.junit.jupiter.api.Test; + +import static org.assertj.core.api.Assertions.assertThat; + +/** + * Tests for {@link FilteringStatusListener}. + * + * @author Dmytro Nosan + */ +class FilteringStatusListenerTests { + + private final DelegateStatusListener delegate = new DelegateStatusListener(); + + @Test + void shouldFilterOutInfoStatus() { + FilteringStatusListener listener = createListener(Status.WARN); + InfoStatus info = new InfoStatus("info", getClass()); + WarnStatus warn = new WarnStatus("warn", getClass()); + ErrorStatus error = new ErrorStatus("error", getClass()); + listener.addStatusEvent(info); + listener.addStatusEvent(warn); + listener.addStatusEvent(error); + assertThat(this.delegate.getStatuses()).containsExactly(warn, error); + } + + @Test + void shouldStartUnderlyingStatusListener() { + FilteringStatusListener listener = createListener(Status.INFO); + assertThat(this.delegate.isStarted()).isFalse(); + listener.start(); + assertThat(this.delegate.isStarted()).isTrue(); + } + + @Test + void shouldStopUnderlyingStatusListener() { + FilteringStatusListener listener = createListener(); + this.delegate.start(); + assertThat(this.delegate.isStarted()).isTrue(); + listener.stop(); + assertThat(this.delegate.isStarted()).isFalse(); + } + + @Test + void shouldUseResetResistantValueFromUnderlyingStatusListener() { + FilteringStatusListener listener = createListener(); + assertThat(listener.isResetResistant()).isEqualTo(this.delegate.isResetResistant()); + } + + private FilteringStatusListener createListener() { + return new FilteringStatusListener(this.delegate, Status.INFO); + } + + private FilteringStatusListener createListener(int levelThreshold) { + return new FilteringStatusListener(this.delegate, levelThreshold); + } + + private static final class DelegateStatusListener implements StatusListener, LifeCycle { + + private final List statuses = new ArrayList<>(); + + private boolean started = false; + + @Override + public void addStatusEvent(Status status) { + this.statuses.add(status); + } + + List getStatuses() { + return this.statuses; + } + + @Override + public boolean isResetResistant() { + return true; + } + + @Override + public void start() { + this.started = true; + } + + @Override + public void stop() { + this.started = false; + } + + @Override + public boolean isStarted() { + return this.started; + } + + } + +} diff --git a/spring-boot-project/spring-boot/src/test/java/org/springframework/boot/logging/logback/LogbackLoggingSystemTests.java b/spring-boot-project/spring-boot/src/test/java/org/springframework/boot/logging/logback/LogbackLoggingSystemTests.java index 6152cfb3fdff..4b7e57bfe744 100644 --- a/spring-boot-project/spring-boot/src/test/java/org/springframework/boot/logging/logback/LogbackLoggingSystemTests.java +++ b/spring-boot-project/spring-boot/src/test/java/org/springframework/boot/logging/logback/LogbackLoggingSystemTests.java @@ -1,5 +1,5 @@ /* - * Copyright 2012-2024 the original author or authors. + * Copyright 2012-2025 the original author or authors. * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. @@ -32,12 +32,18 @@ import ch.qos.logback.classic.Level; import ch.qos.logback.classic.Logger; import ch.qos.logback.classic.LoggerContext; +import ch.qos.logback.classic.spi.ILoggingEvent; import ch.qos.logback.classic.spi.LoggerContextListener; +import ch.qos.logback.core.AppenderBase; import ch.qos.logback.core.ConsoleAppender; import ch.qos.logback.core.encoder.LayoutWrappingEncoder; import ch.qos.logback.core.joran.spi.JoranException; import ch.qos.logback.core.rolling.RollingFileAppender; import ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy; +import ch.qos.logback.core.status.OnConsoleStatusListener; +import ch.qos.logback.core.status.OnErrorConsoleStatusListener; +import ch.qos.logback.core.status.Status; +import ch.qos.logback.core.status.StatusListener; import ch.qos.logback.core.util.DynamicClassLoadingException; import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.BeforeEach; @@ -649,12 +655,41 @@ void logbackDebugPropertyIsHonored(CapturedOutput output) { assertThat(output).contains("LevelChangePropagator") .contains("SizeAndTimeBasedFileNamingAndTriggeringPolicy") .contains("DebugLogbackConfigurator"); + LoggerContext loggerContext = this.logger.getLoggerContext(); + List statusListeners = loggerContext.getStatusManager().getCopyOfStatusListenerList(); + assertThat(statusListeners).hasSize(1); + StatusListener statusListener = statusListeners.get(0); + assertThat(statusListener).isInstanceOf(OnConsoleStatusListener.class); } finally { System.clearProperty("logback.debug"); } } + @Test + void logbackErrorStatusListenerShouldBeRegistered(CapturedOutput output) { + this.loggingSystem.beforeInitialize(); + initialize(this.initializationContext, null, getLogFile(tmpDir() + "/tmp.log", null)); + LoggerContext loggerContext = this.logger.getLoggerContext(); + List statusListeners = loggerContext.getStatusManager().getCopyOfStatusListenerList(); + assertThat(statusListeners).hasSize(1); + StatusListener statusListener = statusListeners.get(0); + assertThat(statusListener).isInstanceOf(FilteringStatusListener.class); + assertThat(statusListener).hasFieldOrPropertyWithValue("levelThreshold", Status.ERROR); + assertThat(statusListener).extracting("delegate").isInstanceOf(OnErrorConsoleStatusListener.class); + AppenderBase appender = new AppenderBase<>() { + @Override + protected void append(ILoggingEvent eventObject) { + throw new IllegalStateException("Fail to append"); + } + }; + this.logger.addAppender(appender); + appender.setContext(loggerContext); + appender.start(); + this.logger.info("Hello world"); + assertThat(output).contains("Fail to append").contains("Hello world"); + } + @Test void testRollingFileNameProperty() { String rollingFile = "my.log.%d{yyyyMMdd}.%i.gz"; diff --git a/spring-boot-tests/spring-boot-smoke-tests/spring-boot-smoke-test-structured-logging/src/main/java/smoketest/structuredlogging/DuplicateJsonMembersCustomizer.java b/spring-boot-tests/spring-boot-smoke-tests/spring-boot-smoke-test-structured-logging/src/main/java/smoketest/structuredlogging/DuplicateJsonMembersCustomizer.java new file mode 100644 index 000000000000..c76bcbba301b --- /dev/null +++ b/spring-boot-tests/spring-boot-smoke-tests/spring-boot-smoke-test-structured-logging/src/main/java/smoketest/structuredlogging/DuplicateJsonMembersCustomizer.java @@ -0,0 +1,32 @@ +/* + * Copyright 2012-2025 the original author or authors. + * + * Licensed 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 smoketest.structuredlogging; + +import java.util.Objects; + +import org.springframework.boot.json.JsonWriter.Members; +import org.springframework.boot.logging.structured.StructuredLoggingJsonMembersCustomizer; + +public class DuplicateJsonMembersCustomizer implements StructuredLoggingJsonMembersCustomizer { + + @Override + public void customize(Members members) { + members.add("test").as(Objects::toString); + members.add("test").as(Objects::toString); + } + +} diff --git a/spring-boot-tests/spring-boot-smoke-tests/spring-boot-smoke-test-structured-logging/src/main/resources/application.properties b/spring-boot-tests/spring-boot-smoke-tests/spring-boot-smoke-test-structured-logging/src/main/resources/application.properties index 4d8f17b7f94f..000769604f46 100644 --- a/spring-boot-tests/spring-boot-smoke-tests/spring-boot-smoke-test-structured-logging/src/main/resources/application.properties +++ b/spring-boot-tests/spring-boot-smoke-tests/spring-boot-smoke-test-structured-logging/src/main/resources/application.properties @@ -7,3 +7,6 @@ logging.structured.json.customizer=smoketest.structuredlogging.SampleJsonMembers #--- spring.config.activate.on-profile=custom logging.structured.format.console=smoketest.structuredlogging.CustomStructuredLogFormatter +#--- +spring.config.activate.on-profile=on-error +logging.structured.json.customizer=smoketest.structuredlogging.DuplicateJsonMembersCustomizer diff --git a/spring-boot-tests/spring-boot-smoke-tests/spring-boot-smoke-test-structured-logging/src/test/java/smoketest/structuredlogging/SampleStructuredLoggingApplicationTests.java b/spring-boot-tests/spring-boot-smoke-tests/spring-boot-smoke-test-structured-logging/src/test/java/smoketest/structuredlogging/SampleStructuredLoggingApplicationTests.java index 2eb7e2b2dab7..2d60bb8c8f1b 100644 --- a/spring-boot-tests/spring-boot-smoke-tests/spring-boot-smoke-test-structured-logging/src/test/java/smoketest/structuredlogging/SampleStructuredLoggingApplicationTests.java +++ b/spring-boot-tests/spring-boot-smoke-tests/spring-boot-smoke-test-structured-logging/src/test/java/smoketest/structuredlogging/SampleStructuredLoggingApplicationTests.java @@ -1,5 +1,5 @@ /* - * Copyright 2012-2024 the original author or authors. + * Copyright 2012-2025 the original author or authors. * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. @@ -65,4 +65,10 @@ void custom(CapturedOutput output) { assertThat(output).contains("epoch=").contains("msg=\"Starting SampleStructuredLoggingApplication"); } + @Test + void shouldCaptureCustomizerError(CapturedOutput output) { + SampleStructuredLoggingApplication.main(new String[] { "--spring.profiles.active=on-error" }); + assertThat(output).contains("The name 'test' has already been written"); + } + } From 33849f82b4fac816b0aa36fcbca81ceba66c5c1d Mon Sep 17 00:00:00 2001 From: Moritz Halbritter Date: Mon, 13 Jan 2025 11:34:10 +0100 Subject: [PATCH 2/2] Polish "Logback StructuredLogFormatter exceptions are not visible to the user" See gh-43575 --- .../boot/logging/logback/FilteringStatusListener.java | 2 +- .../boot/logging/logback/LogbackLoggingSystem.java | 6 ++++-- 2 files changed, 5 insertions(+), 3 deletions(-) diff --git a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/FilteringStatusListener.java b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/FilteringStatusListener.java index b2625044a646..247272bb8566 100644 --- a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/FilteringStatusListener.java +++ b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/FilteringStatusListener.java @@ -27,7 +27,7 @@ * * @author Dmytro Nosan */ -final class FilteringStatusListener extends ContextAwareBase implements StatusListener, LifeCycle { +class FilteringStatusListener extends ContextAwareBase implements StatusListener, LifeCycle { private final StatusListener delegate; diff --git a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/LogbackLoggingSystem.java b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/LogbackLoggingSystem.java index d143b37fb258..ebb47f9a619d 100644 --- a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/LogbackLoggingSystem.java +++ b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/LogbackLoggingSystem.java @@ -495,8 +495,10 @@ private void addOnErrorConsoleStatusListener(LoggerContext context) { FilteringStatusListener listener = new FilteringStatusListener(new OnErrorConsoleStatusListener(), Status.ERROR); listener.setContext(context); - context.getStatusManager().add(listener); - listener.start(); + boolean effectivelyAdded = context.getStatusManager().add(listener); + if (effectivelyAdded) { + listener.start(); + } } void setStatusPrinterStream(PrintStream stream) {