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?

Elenoraelenore

Can you post code of your class com.my.app.MyTest? – Forget

nothing special, this is where I have an error logging code: logger.error("error occured", e) – Elenoraelenore

Answer 1

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.

Elenoraelenore

How do you generate this mock exception? Even a "Mock" exception should have a stack trace – Deluxe

with org.mockito.Mockito.mock for example: IncorrectResultSizeDataAccessException exc = mock(IncorrectResultSizeDataAccessException.class); – Elenoraelenore

Have you reported the bug? If no I can do that since it still is reproducible – Tijerina

Answer 2

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.

Deluxe

then it looks like it is a bug in log4j2 – Elenoraelenore

Possibly. But I don't think it is a normal behavior for an exception to have a null stack trace. From the doc: a virtual machine that has no stack trace information concerning this thread is permitted to return a zero-length array from this method so at worst it would return an empty array. You can still report a bug, but I would be more interested in the code actually throwing your Throwable! Can you provide it? – Deluxe

Sun JVM seems to do this sometimes: #2411987. If you are using the Sun JVM, maybe using the flag -XX:-OmitStackTraceInFastThrow would solve your issue – Deluxe

I am throwing the following exception in the try part which is logged in the catch part: throw new IncorrectResultSizeDataAccessException(EXPECTED_RESULT_SIZE, result); – Elenoraelenore

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. – Elenoraelenore

This answer should have been accepted rather than OP’s own answer. – Forget

Answer 3

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;
}

Unbelt