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 spring-projectsgh-43384

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;
+	}
+
+}

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);
 	}

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<Status> statuses = new ArrayList<>();
+
+		private boolean started = false;
+
+		@Override
+		public void addStatusEvent(Status status) {
+			this.statuses.add(status);
+		}
+
+		List<Status> 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;
+		}
+
+	}
+
+}

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<StatusListener> 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<StatusListener> 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<ILoggingEvent> 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";

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<Object> {
+
+	@Override
+	public void customize(Members<Object> members) {
+		members.add("test").as(Objects::toString);
+		members.add("test").as(Objects::toString);
+	}
+
+}

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

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");
+	}
+
 }