StructuredLogFormatter exceptions are not visible to the user

[philwebb]

Currently, if StructuredLogFormatter throws an exception it is silently swallowed and the user doesn't know something has gone wrong. PR #43371 provides one possible fix where we print the exception directly, however, we might be better trying to hook into the support of the underlying logging framework.

Logback has the concept of a Status event which it uses to pass exceptions raised from a LogEncoder. It also has a OnErrorConsoleStatusListener which will print errors to System.err.

Log4J2 has a DefaultErrorHandler which either ignores exceptions or throws a AppenderLoggingException.

[mhalbritter]

Logback documentation: https://logback.qos.ch/manual/configuration.html#dumpingStatusData

Enabling output of status data usually goes a long way in the diagnosis of issues with logback. Note that errors can also occur post-configuration, e.g. when a disk a full or log files cannot be archived due to permission errors. As such, it is highly recommended that you register a StatusListener as discussed below.

[quaff]

Log4j2 is not affected, it will fallback to

2024-12-05T03:03:25.342929Z main ERROR An exception occurred processing Appender Console java.lang.IllegalStateException: The name 'test' has already been written
	at org.springframework.util.Assert.state(Assert.java:101)
	at org.springframework.boot.json.JsonValueWriter.writePair(JsonValueWriter.java:228)
	at org.springframework.boot.json.JsonValueWriter.write(JsonValueWriter.java:83)
	at org.springframework.boot.json.JsonWriter$Member.write(JsonWriter.java:650)
	at org.springframework.boot.json.JsonWriter$Members.write(JsonWriter.java:339)
	at org.springframework.boot.json.JsonWriter.lambda$of$2(JsonWriter.java:153)
	at org.springframework.boot.json.JsonWriter.lambda$withSuffix$1(JsonWriter.java:126)
	at org.springframework.boot.json.JsonWriter.lambda$write$0(JsonWriter.java:103)
	at org.springframework.boot.json.WritableJson$1.to(WritableJson.java:164)
	at org.springframework.boot.json.WritableJson.toWriter(WritableJson.java:149)
	at org.springframework.boot.json.WritableJson.toByteArray(WritableJson.java:80)
	at org.springframework.boot.logging.structured.JsonWriterStructuredLogFormatter.formatAsBytes(JsonWriterStructuredLogFormatter.java:84)
	at org.springframework.boot.logging.log4j2.StructuredLogLayout.toByteArray(StructuredLogLayout.java:66)
	at org.apache.logging.log4j.core.layout.AbstractLayout.encode(AbstractLayout.java:207)
	at org.apache.logging.log4j.core.layout.AbstractLayout.encode(AbstractLayout.java:36)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:227)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:220)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:211)
	at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:160)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:133)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:124)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:88)
	at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:714)
	at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:672)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:648)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:584)
	at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:92)
	at org.apache.logging.log4j.core.Logger.log(Logger.java:240)

[quaff]

For Logback, unwanted INFO level status can not be filtered out if we register OnErrorConsoleStatusListener.

11:16:56,207 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@4007f65e - Propagating ERROR level on Logger[org.apache.catalina.startup.DigesterFactory] onto the JUL framework
11:16:56,208 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@4007f65e - Propagating ERROR level on Logger[org.apache.catalina.util.LifecycleBase] onto the JUL framework
11:16:56,209 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@4007f65e - Propagating WARN level on Logger[org.apache.coyote.http11.Http11NioProtocol] onto the JUL framework
11:16:56,209 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@4007f65e - Propagating WARN level on Logger[org.apache.sshd.common.util.SecurityUtils] onto the JUL framework
11:16:56,209 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@4007f65e - Propagating WARN level on Logger[org.apache.tomcat.util.net.NioSelectorPool] onto the JUL framework
11:16:56,209 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@4007f65e - Propagating ERROR level on Logger[org.eclipse.jetty.util.component.AbstractLifeCycle] onto the JUL framework
11:16:56,209 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@4007f65e - Propagating WARN level on Logger[org.hibernate.validator.internal.util.Version] onto the JUL framework
11:16:56,209 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@4007f65e - Propagating WARN level on Logger[org.springframework.boot.actuate.endpoint.jmx] onto the JUL framework
11:16:56,249 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@4007f65e - Propagating INFO level on Logger[ROOT] onto the JUL framework
11:16:56,310 |-ERROR The name 'test' has already been written java.lang.IllegalStateException: The name 'test' has already been written
	at java.lang.IllegalStateException: The name 'test' has already been written
	at 	at org.springframework.util.Assert.state(Assert.java:101)
	at 	at org.springframework.boot.json.JsonValueWriter.writePair(JsonValueWriter.java:228)
	at 	at org.springframework.boot.json.JsonValueWriter.write(JsonValueWriter.java:83)
	at 	at org.springframework.boot.json.JsonWriter$Member.write(JsonWriter.java:650)
	at 	at org.springframework.boot.json.JsonWriter$Members.write(JsonWriter.java:339)
	at 	at org.springframework.boot.json.JsonWriter.lambda$of$2(JsonWriter.java:153)
	at 	at org.springframework.boot.json.JsonWriter.lambda$withSuffix$1(JsonWriter.java:126)
	at 	at org.springframework.boot.json.JsonWriter.lambda$write$0(JsonWriter.java:103)
	at 	at org.springframework.boot.json.WritableJson$1.to(WritableJson.java:164)
	at 	at org.springframework.boot.json.WritableJson.toWriter(WritableJson.java:149)
	at 	at org.springframework.boot.json.WritableJson.toByteArray(WritableJson.java:80)
	at 	at org.springframework.boot.logging.structured.JsonWriterStructuredLogFormatter.formatAsBytes(JsonWriterStructuredLogFormatter.java:84)
	at 	at org.springframework.boot.logging.logback.StructuredLogEncoder.encode(StructuredLogEncoder.java:130)
	at 	at org.springframework.boot.logging.logback.StructuredLogEncoder.encode(StructuredLogEncoder.java:1)

I still think ex.printStackTrace(System.err) is better choice.

[mhalbritter]

We could implement a FilteringStatusListener which delegates to OnErrorConsoleStatusListener and check the status in addStatusEvent and only delegate if the status level is WARN or above.

I still think ex.printStackTrace(System.err) is better choice.

I don't. We should not circumvent the status logging facilities in Logback.