Logback: Logging Exceptions with null message cause NullPointerException thrown by LoggingAppender and no log issued

[nexteam-silviot]

Hello,
we're using the latest java-logging-logback library for our Google Cloud infrastructure with the LogbackAppender that appends on Stackdriver.

<dependency>
<groupId>com.google.cloud</groupId>
<artifactId>google-cloud-logging-logback</artifactId>
<version>0.118.5-alpha</version>
</dependency>

When logging particular Exceptions with a null message the class com.google.cloud.logging.logback.LoggingAppender throws a NullPointerException and the log is not printed on the appender.

Putting the logback configuration in debug mode, on stdout an appender Exception is printed but the previously logged Exception is lost.

Steps to reproduce

1. Use LoggingAppender and enable debug mode

<configuration debug="true">
...
<appender name="CLOUD" class="com.google.cloud.logging.logback.LoggingAppender">
<!-- Optional : filter logs at or above a level -->
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>DEBUG</level>
</filter>
<log>test</log>
<flushLevel>DEBUG</flushLevel>
</appender>

2. Call logger.error()

logger.error(new NullPointerException());

3. You will get a NullPointerException from LoggingAppender on stdout and the occurred Exception is not logged

19:33:00,377 |-ERROR in com.google.cloud.logging.logback.LoggingAppender[CLOUD] - Appender [CLOUD] failed to append. java.lang.NullPointerException
at java.lang.NullPointerException
at at java.base/java.lang.StringBuilder.(Unknown Source)
at at com.google.cloud.logging.logback.LoggingAppender.logEntryFor(LoggingAppender.java:294)
at at com.google.cloud.logging.logback.LoggingAppender.append(LoggingAppender.java:231)
at at com.google.cloud.logging.logback.LoggingAppender.append(LoggingAppender.java:79)
at at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
at at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
at at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
at at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
at at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:422)
at at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:384)
at at ch.qos.logback.classic.Logger.error(Logger.java:539)
at at com.test.logger.impl.Slf4jLogger.error(Slf4jLogger.java:140)
at at com.test.resources.PingResource.ping(PingResource.java:41)
at at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
at at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

Where the Issue is located

The issue can be found in the LoggingAppender source, in logEntryFor function (row 294):

  private LogEntry logEntryFor(ILoggingEvent e) {
    StringBuilder payload = new StringBuilder(e.getFormattedMessage()).append('\n');
    writeStack(e.getThrowableProxy(), "", payload);

    Level level = e.getLevel();
    Severity severity = severityFor(level);

At the first row, StringBuilder constructor throws NullPointerException because it expects a not-null string.

Fix suggestion

A way to fix the issue is to instantiate StringBuilder with no parameters then call append() passing the formatted message as append() is null safe.

  private LogEntry logEntryFor(ILoggingEvent e) {
    StringBuilder payload = new StringBuilder().append(e.getFormattedMessage()).append('\n');
    writeStack(e.getThrowableProxy(), "", payload);

    Level level = e.getLevel();
    Severity severity = severityFor(level);

Thank you for your attention!

[athakor]

@nexteam-silviot Thanks for these issue, I am able to reproduce it and will raise PR soon.

StackTrace

17:54:02,444 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [com.google.cloud.logging.logback.LoggingAppender]
17:54:02,756 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [CLOUD]
17:54:12,610 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
17:54:12,610 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
17:54:12,626 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
17:54:12,657 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
17:54:12,657 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CLOUD] to Logger[ROOT]
17:54:12,657 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
17:54:12,657 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@1b266842 - Registering current configuration as safe fallback point
17:54:12,673 |-ERROR in com.google.cloud.logging.logback.LoggingAppender[CLOUD] - Appender [CLOUD] failed to append. java.lang.NullPointerException
	at java.lang.NullPointerException
	at 	at java.lang.StringBuilder.<init>(StringBuilder.java:112)
	at 	at com.google.cloud.logging.logback.LoggingAppender.logEntryFor(LoggingAppender.java:294)
	at 	at com.google.cloud.logging.logback.LoggingAppender.append(LoggingAppender.java:231)
	at 	at com.google.cloud.logging.logback.LoggingAppender.append(LoggingAppender.java:79)
	at 	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
	at 	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
	at 	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
	at 	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
	at 	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
	at 	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
	at 	at ch.qos.logback.classic.Logger.error(Logger.java:522)