Skip to content

StructuredLogFormatter exceptions are not visible to the user #43384

Closed as not planned
Closed as not planned
StructuredLogFormatter exceptions are not visible to the user#43384
Labels
status: supersededAn issue that has been superseded by another

Description

@philwebb
philwebb
opened on Dec 4, 2024

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.

Activity

  1. philwebb
    added
    type: enhancementA general enhancement
    on Dec 4, 2024
  2. philwebb
    modified the milestones: 3.5.x, 3.x on Dec 4, 2024

  3. mhalbritter commented on Dec 4, 2024

    @mhalbritter
    mhalbritter
    on Dec 4, 2024
    Contributor

    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.

  4. quaff commented on Dec 5, 2024

    @quaff
    quaff
    on Dec 5, 2024
    Contributor

    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)

  5. quaff commented on Dec 5, 2024

    @quaff
    quaff
    on Dec 5, 2024
    Contributor

    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.

  6. mhalbritter commented on Dec 5, 2024

    @mhalbritter
    mhalbritter
    on Dec 5, 2024
    Contributor

    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.

  7. mhalbritter commented on Jan 7, 2025

    @mhalbritter
    mhalbritter
    on Jan 7, 2025
    Contributor

    Closing in favor of #43575.

  8. mhalbritter
    closed this as not plannedon Jan 7, 2025
  9. mhalbritter
    removed this from the 3.x milestone on Jan 7, 2025
  10. mhalbritter
    added
    status: supersededAn issue that has been superseded by another
    and removed
    type: enhancementA general enhancement
    on Jan 7, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    status: supersededAn issue that has been superseded by another

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions