From 11461d07b6e3aed2b939fe7b81ab84cf917681e7 Mon Sep 17 00:00:00 2001 From: Dmytro Nosan Date: Thu, 19 Dec 2024 14:40:56 +0200 Subject: [PATCH] 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-43384 --- .../logback/FilteringStatusListener.java | 80 ++++++++++++ .../logging/logback/LogbackLoggingSystem.java | 12 ++ .../logback/FilteringStatusListenerTests.java | 121 ++++++++++++++++++ .../logback/LogbackLoggingSystemTests.java | 35 +++++ .../DuplicateJsonMembersCustomizer.java | 32 +++++ .../src/main/resources/application.properties | 3 + ...mpleStructuredLoggingApplicationTests.java | 6 + 7 files changed, 289 insertions(+) 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..dc8d0f2df9a9 --- /dev/null +++ b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/FilteringStatusListener.java @@ -0,0 +1,80 @@ +/* + * Copyright 2012-2024 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 e30da9139bf0..417899bdc11f 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..419c1ab6f524 --- /dev/null +++ b/spring-boot-project/spring-boot/src/test/java/org/springframework/boot/logging/logback/FilteringStatusListenerTests.java @@ -0,0 +1,121 @@ +/* + * Copyright 2012-2024 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..b6cdccf1d748 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 @@ -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..d66d1e63c94d --- /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-2024 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..ca85f1c0d0fb 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 @@ -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"); + } + }