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.
Comment From: 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.
Comment From: 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)
Comment From: 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.
Comment From: 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.
Comment From: mhalbritter
Closing in favor of #43575.