log4j not printing the stacktrace for exceptions

Question

I am using log4j with tomcat. When I log exceptions in my JSPs, servlets:

private Logger _log = Logger.getLogger(this.getClass());
...
try{...} catch (Exception e) {
    _log.error("Error refreshing all prices", e);
}

I only get the first line of the exception, without a stacktrace.

17-Feb 17:37:45 ERROR AutoContrib:175 - Exception while publishing csv file: java.lang.ArrayIndexOutOfBoundsException

Not very helpful at all!

My log4j.properties file (/tomcat/common/classes/log4j.properties) looks like this:

log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{dd-MMM HH:mm:ss} %5p %c{1}:%L - %m%n
log4j.appender.stdout.threshold=info

log4j.appender.file=org.apache.log4j.RollingFileAppender
log4j.appender.file.maxFileSize=5000KB
log4j.appender.file.maxBackupIndex=10
log4j.appender.file.File=${catalina.home}/logs/web.log
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%d{dd-MMM HH:mm:ss} %5p %c{1}:%L - %m%n
log4j.appender.file.threshold=info

log4j.rootLogger=debug, stdout, file

Solution 1

Actually, it's probably due to a hotspot optimization: after a certain number of the same exception being thrown it stops printing out trace. This can be turned off with a VM arg, see:

From http://www.oracle.com/technetwork/java/javase/relnotes-139183.html :

The compiler in the server VM now provides correct stack backtraces for all "cold" built-in exceptions. For performance purposes, when such an exception is thrown a few times, the method may be recompiled. After recompilation, the compiler may choose a faster tactic using preallocated exceptions that do not provide a stack trace. To disable completely the use of preallocated exceptions, use this new flag: -XX:-OmitStackTraceInFastThrow.

More here:

http://jawspeak.com/2010/05/26/hotspot-caused-exceptions-to-lose-their-stack-traces-in-production-and-the-fix/

Solution 2

What you have posted should display the stack trace as stated in the javadoc.

Note that if you don't include a message (and just call logger.error(ex)) then the stack trace is not logged.

Solution 3

There are two overloaded methods for error method.

1. logger.error(ex);
2. logger.error("some oops string ", ex);

if you use 1st method , which will only print the name of the Exception. if you use 2nd method, some message along with exception which will print complete stack trace similar to e.printStackTrace() method.

Solution 4

Like answered by @Luhar above, I struggled with same thing and finally this worked for me; Good thing about this approach is we don't have to tinker with system level settings like JVM, Log4J since we never know it may lead to new unexpected surprise !

try {

...
..

} catch (Exception er) {
        ByteArrayOutputStream os = new ByteArrayOutputStream();
        er.printStackTrace(new PrintStream(os));
        LOGGER.error(new String(os.toByteArray()));
        //LOGGER.error(er);
}

Solution 5

You can add these lines of code in your catch block.

catch (SQLException e) {
            CharArrayWriter cw = new CharArrayWriter();
            PrintWriter w = new PrintWriter(cw);
            e.printStackTrace(w);
            w.close();
            String trace = cw.toString();

    log.error("This is complete stacktrace", trace);
}

View more solutions

Comments

[Ryan]

Thanks for the advice! I will try this now. BTW, for the singleton approach you can't use 'this' with the static getLoggger(). I guess I can use getLogger(MyClass.class)

[Buhake Sindi]

True Ryan!. It makes instantiation faster seeing that the singleton already exists after creation.

[Bozho]

ideally, he shouldn't need this

[Bozho]

ideally, he shouldn't need this

[objects]

that changes the stack trace to be the state of the current thread. It will no longer be the stack trace for the thrown exception

[Buhake Sindi]

That's correct, Definition of fillInStackTrace(): Fills in the execution stack trace. This method records within this Throwable object information about the current state of the stack frames for the current thread. and that's what we want. So recording all the stack frames from the thread that executed it. After all, Web apps especially are thread-executed, so that makes perfect sense.

[objects]

the stack trace of the thread is different from the stack trace of the exception. The stack trace of the exception shows where the exception occurred, the stack trace of the thread (in this case) shows where the exception was caught.

[Buhake Sindi]

I understand what you're saying @objects, fillInStackTrace also records the Cause of the exception. So you can ideally check in the cause to see where the fault lies.

[objects]

fillInStackTrace does not record the cause afaik, it (the cause) is set when the exception is created (fillInStackTrace is also called at that point)

[rbwhitaker]

Ah. There it is. This is what was biting me. Logging an error doesn't print the stack trace. You need to log a message with the error to get that.

[Charles Morin]

This was helpful. Thank you. Can we configure log4j so it display a full trace even if we just provide the exception object?

[JTW]

Why Java... why...?

[mukunda]

Nothing like banging your head on a production system with a "java.lang.NullPointerException" and trying to figure out where in the class it is.