Slf4j with Log4j does not print wrapped exception

问题:

First example:

public class Main {

    private static final Logger logger = LoggerFactory.getLogger(Main.class);

    public static void main(String[] args) throws Exception {
        try {
            throw new RuntimeException(new NullPointerException("NPE"));
        } catch (RuntimeException e) {
            logger.error("Error:", e);
        }
    }
}

Output:

Error:
java.lang.RuntimeException: java.lang.NullPointerException: NPE
    at Main.main(Main.java:10)

In the second example we just add a message to the RuntimeException also:

throw new RuntimeException("RTE", new NullPointerException("NPE"));

Output:

Error:
java.lang.RuntimeException: RTE
    at Main.main(Main.java:10)

Why is NullPointerException not logged in this case?

Note: e.printStackTrace() prints both exceptions in both cases:

java.lang.RuntimeException: RTE
    at Main.main(Main.java:10)
Caused by: java.lang.NullPointerException: NPE
    ... 1 more

Versions:

slf4j-api: 1.7.12
slf4j-log4j12: 1.7.12
log4j: 1.2.17

回答1:

Giving it a possible try using all the docs and debugging I could, I hope this helps in whatever way it can :

  @param message the message object to log.
  @param t the exception to log, including its stack trace.
  public void error(Object message, Throwable t) 

So both your cases are including the stack-trace of the RuntimeException thrown by the statement of code. Not much of a difference.

Case 1 : throw new RuntimeException(new NullPointerException("NPE"));

Quoting from the RuntimeException Java-Doc and NullPointerException Java-Doc

public RuntimeException(Throwable cause)

Constructs a new runtime exception with the specified cause and a detail message of (cause==null ? null : cause.toString()) (which typically contains the class and detail message of cause). This constructor is useful for runtime exceptions that are little more than wrappers for other throwables.

---

public NullPointerException(String s)

Constructs a NullPointerException with the specified detail message.

---

So that possibly answers the first part of your question where java.lang.RuntimeException is thrown during execution which is caused by the new NullPointerException but as cause==null evaluates to false the cause.toString() is printed i.e java.lang.NullPointerException and now since this exception itself has a message passed that follows as NPE

Note : You have mentioned the cause as NullPointerException in your code.(hence cause==null evaluates to false)

Case 2 : throw new RuntimeException("RTE", new NullPointerException("NPE"))

public RuntimeException(String message, Throwable cause)

Constructs a new runtime exception with the specified detail message and cause. Note that the detail message associated with cause is not automatically incorporated in this runtime exception's detail message.

---

In which case you end up getting java.lang.RuntimeException being thrown with a message RTE since your cause is a child of RuntimeException itself and the parent is caught first, it gets executed and the child is not reached in this case.

回答2:

I noticed that in the log4j.properties file I'm using there is the following line:

log4j.throwableRenderer=org.apache.log4j.EnhancedThrowableRenderer

It seems to be causing the caused by elements to be omitted when the exception is logged.

Once removed, the full stack trace is logged.

回答3:

There are 2 issues.

1. Why is NullPointerException not logged in this case[throw new RuntimeException("RTE", new NullPointerException("NPE"));]?

Ans:

Actually SLF4J has no impact on that case. It is pure JVM issue. In JVM, it is required to compute every passed parameter before function call. If you follow this 2 examples, you can easily understood that issue.

Example 1:

public class Main {
    public static void main(String[] args) {
            throw new RuntimeException(new NullPointerException("NPE"));
    }
}

Output:

Exception in thread "main" java.lang.RuntimeException: java.lang.NullPointerException: NPE // Here, "java.lang.NullPointerException: NPE" - this portion is used as message according to RuntimeException
    at Main.main(Main.java:3)
Caused by: java.lang.NullPointerException: NPE
    ... 1 more

Here, "java.lang.NullPointerException: NPE" - this portion is used as message according to RuntimeException which one is also generated from another exception NullPointerException(String s)

Example 2:

public class Main {
    public static void main(String[] args) {
            throw new RuntimeException("RTE", new NullPointerException("NPE"));
    }
}

Output:

Exception in thread "main" java.lang.RuntimeException: RTE // Here "RTE" is used as message
    at Main.main(Main.java:3)
Caused by: java.lang.NullPointerException: NPE
    ... 1 more

Here "RTE" is used as message.

In your code, you have used 3 times exceptions. That's not good coding.

---

2. Why e.printStackTrace() prints both exceptions in both cases?

e.printStackTrace() prints this throwable and its backtrace to the standard error stream. It prints a stack trace for this Throwable object on the error output stream that is the value of the field System.err As your output is:

java.lang.RuntimeException: RTE
    at Main.main(Main.java:10)
Caused by: java.lang.NullPointerException: NPE
    ... 1 more

• The first line of output["java.lang.RuntimeException: RTE"] contains the result of the toString() method for this Throwable object.
• Remaining lines represent data previously recorded by the method fillInStackTrace()

• The backtrace for a throwable with an initialized, non-null cause should generally include the backtrace for the cause. The format of this information depends on the implementation. For your clear understanding, go through the backtrace example below:

  HighLevelException: MidLevelException: LowLevelException
          at Junk.a(Junk.java:13)
          at Junk.main(Junk.java:4)
  Caused by: MidLevelException: LowLevelException
          at Junk.c(Junk.java:23)
          at Junk.b(Junk.java:17)
          at Junk.a(Junk.java:11)
          ... 1 more
  Caused by: LowLevelException
          at Junk.e(Junk.java:30)
          at Junk.d(Junk.java:27)
          at Junk.c(Junk.java:21)
          ... 3 more
  

• "... 1"

  These lines indicate that the remainder of the stack trace for this exception matches the indicated number of frames from the bottom of the stack trace of the exception that was caused by this exception (the "enclosing" exception).

Resource Link:

1. What printstacktrace does?
2. SLF4J-Log4J does not appear to have disabled logging

---

For SLF4J, you can go through

1. sysout-over-slf4j module redirects all calls to System.out and System.err to an SLF4J defined logger with the name of the fully qualified class in which the System.out.println (or similar) call was made, at configurable levels.
2. idalia SLF4J Extensions allows logging at a level determined at runtime rather than compile-time.

回答4:

I had similar problem when I was using Slf4j Logger in my Apache Spark application running on cluster mode. As I found out problem in my case was caused by JVM optimization related to OmitStackTraceInFastThrow which was basically not printing whole stack just top level error without any details.

In your case this might be hiding error message from NullPointerException. Try adding this argument to JVM -XX:-OmitStackTraceInFastThrow when starting your application and let us know if it works.