Sunday, 29 April 2012

Filtering Log4j logs for ERRORs with Stacktraces using grep

I have recently been looking for ways to improve the way we collect information from the logs.  We had a process in support where logs produced through log4j would be grep'd for ERROR messages using something like

grep 'ERROR' application.log

This is OK, but it strips any stack trace information present directly below the ERROR log entry and the stack trace will often give you the information you need to go directly to the source of the problem.

After reading the logging documentation from the excellent dropwizard framework, I was inspired to take a slightly different approach.  Dropwizard uses Logback and has some special handling for outputting stack traces that prefixes the lines with the exclamation mark character.  As far as I know this is not possible using Log4j, but it is possible to match on the default formatting for stack trace information.

By default a log4j log file will look something like this


0    [main] INFO  ExceptionThrower  - making progress
1    [main] INFO  ExceptionThrower  - making progress
2    [main] INFO  ExceptionThrower  - making progress
2    [main] ERROR ExceptionThrower  - Something went wrong
java.lang.Exception: Wrapped the exception
at ExceptionThrower.main(ExceptionThrower.java:21)
Caused by: java.lang.NullPointerException: Something was null
at ExceptionThrower.main(ExceptionThrower.java:18)
... 5 more
5    [main] INFO  ExceptionThrower  - making progress
5    [main] INFO  ExceptionThrower  - making progress


Notice that all of the stack trace lines are prefixed with some whitespace then the word "at".  Grepping on the "at" will only give us the stack and not the error message.  But if we use the --before-context parameter to grep then we can pull in the log error message and the details of the exception:

grep -i '^[[:space:]]*at' --before-context=2 application.log

Using this command will give us just the ERROR message, the subsequent stack trace and the stack trace of the causal exception:

2    [main] ERROR ExceptionThrower  - Something went wrong
java.lang.Exception: Wrapped the exception
        at ExceptionThrower.main(ExceptionThrower.java:21)        
Caused by: java.lang.NullPointerException: Something was null
        at ExceptionThrower.main(ExceptionThrower.java:18)

Any other log statements we are not interested in at this time are omitted.

No comments:

Post a Comment