Monday, 1 September 2008

better stack traces in Java with log4j - including the jar file and version number!

When problems occur in open source software users tend to get stack traces. They often fire them off to some open source mailing list or forum asking for help; often without providing much in the way of detail. One of the first questions asked by support teams is often 'OK, what version are you using'.

Given that its possible to figure out the actual version being used of each class - either using the package information from the MANIFEST or by finding the jar the class came from, it seems logical to include the version information into a stack trace at the end of the line.

One day the JVM might actually do this for us :)

In the meantime, I've created a patch for log4j to add this feature; it appends an optional String to stack traces printed via log4j which includes the jar file name if it can be deduced plus the Java Package version the line of code comes from.

Here's an example...
org.apache.log4j.config.PropertySetterException: Hello
at org.apache.log4j.spi.ThrowableInformationTest.testStackTracePackageName(ThrowableInformationTest.java:306)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [1.5.0]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) [1.5.0]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [1.5.0]
at java.lang.reflect.Method.invoke(Method.java:585) [1.5.0]
at junit.framework.TestCase.runTest(TestCase.java:154) [junit-3.8.1.jar]
at junit.framework.TestCase.runBare(TestCase.java:127) [junit-3.8.1.jar]
at junit.framework.TestResult$1.protect(TestResult.java:106) [junit-3.8.1.jar]
at junit.framework.TestResult.runProtected(TestResult.java:124) [junit-3.8.1.jar]
at junit.framework.TestResult.run(TestResult.java:109) [junit-3.8.1.jar]
at junit.framework.TestCase.run(TestCase.java:118) [junit-3.8.1.jar]
at junit.textui.TestRunner.doRun(TestRunner.java:116) [junit-3.8.1.jar]
at com.intellij.rt.execution.junit.IdeaTestRunner.doRun(IdeaTestRunner.java:94) [idea_rt.jar]
at junit.textui.TestRunner.doRun(TestRunner.java:109) [junit-3.8.1.jar]
at com.intellij.rt.execution.junit.IdeaTestRunner.startRunnerWithArgs(IdeaTestRunner.java:22) [idea_rt.jar]
at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:118) [idea_rt.jar]
at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:40) [idea_rt.jar]
So you can see what version of junit is being used (despite there being no manifest information) along with the JDK implementation version.
e.g.
at java.lang.reflect.Method.invoke(Method.java:585) [1.5.0]
means we found the package number but couldn't find the jar file but we found the implementation version of java.lang.reflect to be 1.5.0. Whereas
at junit.framework.TestCase.run(TestCase.java:118) [junit-3.8.1.jar]
means we found the jar file but the jar file has no manifest version information.

Am hoping one day this gets into some log4j release! You can find the patch here if you're interested.

19 comments:

AnjanBacchuDev said...

Hi James,

cool!

BR,
~A

brianm said...

Brilliant!

Ceki said...

Assuming the version number is the more valuable information, the patch works if either the "ImplementationVersion" is set in the manifest, or if the jar file name includes a version suffix. ImplementationVersion is rarely set and most jars do not have a version suffix, unless they are from a Maven repository.

I have the nagging feeling that extracting the version data will not always work, even if the general idea is pretty brilliant.

Henri said...

It's things like this that will get ImplementationVersion set though :) Hoping it gets in log4j.

Claus Ibsen said...

I am puzzled why this hasn't been added for 3-5 years ago? But very helpful. +1 to get it in log4j.

What about OSGi bundles? Any help there to get the version also?

Jon Scott Stevens said...

OMG, this is the solution to classloader issues! Brilliant! Now, this will be even more brilliant if it could somehow work without needing to patch log4j. =)

James Strachan said...

Ceki - you're right; if folks don't put the version in the jar name or in the manifest, this patch won't help.

However it will work for all jars created via Maven or hosted in a maven repository today (which is quite a large amount of java code) - plus its a great encouragement to anyone using Ant or Eclipse to start filling in that manifest - or including the version number in the jar.

Jon - there's no real reason that the JVM itself can't include this in stack traces; I just figured getting a JVM change in might take a long time :) In the meantime its trivial to take the patch and use it in any Java project; basically whenever a stack trace is created, we can generate a nice versioned stack trace.

Maybe its worth spinning up the code in a little project on google code so folks can easily embed the same feature inside their apps if they like - though I figured including it in the various logging frameworks was probably the simplest route which given how prolific the various logging libraries are - would generally not introduce a new dependency.

Thanks everyone for your comments!

Rob Di Marco said...

Very cool patch. Very sharp thinking on your part. Amazing no one did this before.

I do agree with the commenter on the bug though that it would be nice to be configurable.

But I will definitely keep this patch handy.

James Strachan said...

Have attached another patch that makes it configurable :)

William Louth said...

James are you saying that the following method in the patch accurately determines the class for a method on the callstack? Yes or No?

William

private Class findClass(String className) {
+ try {
+ return Thread.currentThread().getContextClassLoader().loadClass(className);
+ } catch (ClassNotFoundException e) {
+ try {
+ return Class.forName(className);
+ } catch (ClassNotFoundException e1) {
+ try {
+ return getClass().getClassLoader().loadClass(className);
+ } catch (ClassNotFoundException e2) {
+ return null;
+ }
+ }
+ }
+ }

James Strachan said...

William - unfortunately the JVM's StackTrace doesn't expose the actual Class objects which would make the patch pretty trivial. Given the plenthora of different class loader tricks that take place, its the best attempt at finding the class that caused the exception from the stack trace I could think of - typically the thread context class loader is gonna be the active one in most app servers for example.

There's a risk though - it might not be the correct class loader in all cases - but in most cases it should be. (Its certainly better from giving no versioning information ever for any stack trace! :).

Do you have a better way this could be done?

William Louth said...

Yes I do have a solution. I will post it on my blog later as I do not want to get abushed by anti-commercial software and/or logging fanatics.

I just thought I would at least draw attention to the issue which should be noted in the patch (if it is not already).

James Strachan said...

Am looking forward to hearing your solution :)

I didn't realise there were any anti-commercial software or logging fanatics reading my blog comments. I'll keep on the look out for them & try keep them off your back if they do show up! :)

James Strachan said...

William - could you post your blog URL here when you've posted it, so we can see it?

James Strachan said...

am wondering if this is your blog William?

Ceki said...

William Louth:

The findClass(String) method as implemented by James is not guaranteed to get the correct results, especially if the class in question can be found in multiple classloaders that James searches. I think that there is no way to determine with certainty which classloader loaded the class in question given its name (the class' name). AFAIK, only the name of the class is available in StackTraceElement, not the actual class.

There are ways to alleviate this problem. See the logback project,
and in particular http://jira.qos.ch/browse/LBGENERAL-23 for more details.

William Louth said...

williamlouth.wordpress.com is a new blog.

I am just preparing the entry but I can tell you that there is no way of doing this from within the Java runtime itself in an efficient and correct manner. You have to go native. But at least it is possible and it can work with Java 1.2+ runtimes and on all major OS platforms.

StackTraceElement was a design mistake especially as developers are already so comfortable with java.lang.reflect.Method.

William Louth said...

By the way I think we need to abandon logging. Sorry.

It has served it purposes but we need to move beyond the dark ages and consider having a proper diagnostics API as well as dynamic runtime configuration management model that can describe the state pertinent to many different software execution aspects.

Dumping stack traces to a log file is simply wasteful and unproductive when the light shines.

Ramon said...

James, great work yet again.

Love the lateral on that one. Many times I have hunted an issue where this would have helped.

nice.