NullpointerException for console appender for Log4j2

Question

My application logging crashes during maven build in the tests. This is the log4j2.xml what I have in the src/test/resources:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="INFO">
    <Appenders>
        <Console name="stdout" target="SYSTEM_OUT">
            <PatternLayout pattern="MyApp: %d{yyyy-MM-dd HH:mm:ss,SSS} %5p [%t] %c{1.} - %m%n" />
        </Console>
    </Appenders>

    <Loggers>
        <Logger name="com.my.app" level="info" additivity="false">
            <Appender-ref ref="stdout"/>
        </Logger>
        <Root level="error">
            <Appender-ref ref="stdout"/>
        </Root>
    </Loggers>
</Configuration>

And I get this exception during test during build:

2017-11-23 15:12:28,371 main ERROR An exception occurred processing Appender stdout java.lang.NullPointerException
    at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:671)
    at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:138)
    at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:122)
    at org.apache.logging.log4j.core.impl.Log4jLogEvent.getThrownProxy(Log4jLogEvent.java:566)
    at org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:64)
    at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)
    at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:333)
    at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:232)
    at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:217)
    at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:57)
    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:177)
    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:170)
    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:161)
    at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:448)
    at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:433)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
    at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:439)
    at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:434)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:403)
    at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
    at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
    at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2116)
    at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2100)
    at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1994)
    at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1966)
    at org.apache.logging.slf4j.Log4jLogger.error(Log4jLogger.java:319)
    at com.my.app.MyTest.testingMyApp(MyTest.java:89)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
    at org.junit.internal.runners.statements.ExpectException.evaluate(ExpectException.java:19)
    at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
    at org.mockito.internal.runners.JUnit45AndHigherRunnerImpl.run(JUnit45AndHigherRunnerImpl.java:37)
    at org.mockito.runners.MockitoJUnitRunner.run(MockitoJUnitRunner.java:62)
    at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:283)
    at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:173)
    at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153)
    at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:128)
    at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:203)
    at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:155)
    at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)

This is my pom:

<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-api</artifactId>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-web</artifactId>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-slf4j-impl</artifactId>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-jul</artifactId>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-jcl</artifactId>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
</dependency>
<dependency>
    <groupId>org.dblock.log4jna</groupId>
    <artifactId>log4jna-api</artifactId>
</dependency>

The version of log4j is 2.9.1

And the funny thing, that it logs to the console, for example when the spring application starting, then there I can see the logs which are coming from the MyApplication.java which has the @SpringBootApplication annotation.

And MyTest.java:89 is:

logger.error("error occured",e);

And the logger is coming from:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

So it looks like it crashes during error log, but there is no problem if I log a normal info.

So what is this nullpointer?

Answer 1

If you need to create a mock exception with Mockito, you can setup the getStackTrace method to return an empty array of StackTraceElements:

private Throwable logSafeExceptionMock(Class<? extends Throwable> exceptionType) {
  Throwable t = mock(exceptionType);
  when(t.getStackTrace()).thenReturn(new StackTraceElement[0]);
  return t;
}

Answer 2

Ok, I figured it out: it is because in the test class I have a mock exception. If I change it to creating a new object from the exception, it works fine.

It is a good candidate for reporting a bug I guess.

Answer 3

The Exception or Throwable you passed as parameter of logger.error("error occured", e); does not have any stacktrace (its stacktrace is null), however the Log4j2 implementation you are using tries to access said stacktrace and throws this error.

Looking at the source, the line throwing your error is:

stackLength = stackTrace.length;

Meaning that the stackTrace variable is null. It is obtained with throwable.getStackTrace() from the Throwable (Exception) you passed as parameter to

logger.error("error occured", e);

As to why your stacktrace is null, that will depends on the JVM your are using and how you get said Exception. It can happen but that's definitely not a standard behavior. You can take a look at this post and this post.