Bug 45721 - [PATCH] when showing a stack trace - include the relative package versions and optional jar name to aid debugging
[PATCH] when showing a stack trace - include the relative package versions an...
Status: RESOLVED FIXED
Product: Log4j
Classification: Unclassified
Component: Other
1.2
PC Mac OS X 10.4
: P2 normal
: ---
Assigned To: log4j-dev
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2008-09-01 04:31 UTC by James Strachan
Modified: 2014-02-17 13:58 UTC (History)
1 user (show)



Attachments
here's the patch (5.48 KB, patch)
2008-09-01 04:32 UTC, James Strachan
Details | Diff
here's an updated patch that lets this feature be disabled via calling ThrowableInformation.setIncludeVersionInformation(false).set (6.25 KB, patch)
2008-09-02 07:01 UTC, James Strachan
Details | Diff
here's a newer patch which implements Curts ideas (11.74 KB, patch)
2008-09-03 03:21 UTC, James Strachan
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description James Strachan 2008-09-01 04:31:11 UTC
Users tend to get stack traces quite a lot and then they fire them off to some open source mailing list or forum asking for help. One of the first questions 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 if it can be easily deduced.

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

In the meantime, here's a trivial patch which appends an optional String to stack traces printed with 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. 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.
Comment 1 James Strachan 2008-09-01 04:32:19 UTC
Created attachment 22506 [details]
here's the patch
Comment 2 Paul Smith 2008-09-01 17:03:29 UTC
This is a pretty spiffy change I have to say. I'd love to make this a configuration option though rather than committing to it for every single exception.  Experience says that some people just won't want this extra detail.

I can't believe no-ones thought of this one before, this is pretty useful information for triaging issues with remote customers.  Nice one.
Comment 3 James Strachan 2008-09-02 01:17:17 UTC
thanks Paul :) 

I did try to make it configurable; but that'd need a bigger refactor as there's no real way to access any context from the ThrowableInformation - unless we just make it a static property that can be initialised on startup via some system property?

I figure lets enable it by default as its low noise (stack traces are already huge and its typically only gonna print a small version string most of the time - in the middle of the stack trace that few users actually look at anyway - they only read the first line which would have no version information in it anyway); then lets folks disable it explicitly via log4j.xml/properties if they really wish.

BTW the ultimate end user might not think they want this - but when they hit an issue - the poor person on the open source list trying to figure out their issue will really want it! I'd hugely recommend that users have to go out of their way to disable this; as having it on by default will help loads of us open source hackers support our libraries/projects that get embedded in a zillion projects out there.
Comment 4 James Strachan 2008-09-02 07:01:50 UTC
Created attachment 22514 [details]
here's an updated patch that lets this feature be disabled via calling ThrowableInformation.setIncludeVersionInformation(false).set

Here's an improved patch that lets folks disable this feature too. Its way too important and useful to all log4j using projects out there to have this disabled by default - but this allows folks to disable it if they want
Comment 5 Curt Arnold 2008-09-02 08:05:09 UTC
How do JVMs format stack traces for non-english locales?  Do they start with
"at" as the implementation requires.

I'd be surprised if this didn't break the unit tests, at least if the tests
were running against a log4j.jar.

The desired behavior could be configurable if it were moved into PatternLayout
or better, EnhancedPatternLayout.  Currently both of those return true for
ignoreThrowable which delegates the stack trace formatting to the
WriterAppender and ThrowableInformation.   When configured for the enhanced
stack trace, the layout would return false and format the stack trace itself.  
If moved into EnhancedPatternLayout, the implementation could use the JDK 1.4
Throwable.getStackTrace method and avoid attempting to parse the
printStackTrace output since extras requires JDK 1.4 or later.  Could add a
stackTrace property to EnhancedPatternLayout with values: none, default and
enhanced.

As for JVM implementation, you could bounce the idea off
dev@geronimo.apache.org and see their thoughts.
Comment 6 Paul Smith 2008-09-02 14:57:28 UTC
In regards to the non-English locales, how exactly does one configure the JVM to use non-English stack traces?  Looking at the Throwable.printStackTrace() there's a hard-coded 'at':

    public void printStackTrace(PrintStream s) {
        synchronized (s) {
            s.println(this);
            StackTraceElement[] trace = getOurStackTrace();
            for (int i=0; i < trace.length; i++)
                s.println("\tat " + trace[i]);
....


So I don't think there's any locale issue to worry about here.  I tend to agree with James that having this as the default behaviour is a really good thing, but probably going to be controversial (50% love it, 50% will rant on the list that they hate it and demand to change the default behaviour - I think it's just one of those things).

For this reason I would tend to agree with Curt that leaving the default behaviour as it is is probably the safer option initially (log4j 2.0 however could be different ball game).  EnhancedPatternLayout maybe more flexible generally.  The other option to consider is having the option enabled/disable in the DOMConfiguration layer as 'log4j.debug' is tuned:

e.g. in log4j.xml:

<log4j:configuration debug="false" threshold="debug" enhancedStackTraces="true" ...

Having both a general log4j configuration and EnhancedPatternLayout would cover all flexibilities (a general log4j environment switch, as well as per-layout options as needed).
Comment 7 James Strachan 2008-09-03 03:21:47 UTC
Created attachment 22519 [details]
here's a newer patch which implements Curts ideas

Based on the feedback of this thread, I've refactored the patch.

* there's a helper method on ThrowableInformation.getThrowableStrRep(true) to get an enhanced format (in case anyone wants it) but by default it remains unchanged

* the PatternLayout now has a property ExtendedStackTrace which is off by default

So out of the box there are no changes to log4j's output and all the tests still pass.

But if you enable ExtendedStackTrace on the layout you get the extended stack trace. You can do this via XML or via the properties file...

e.g. 

log4j.appender.testAppender.layout=org.apache.log4j.MyPatternLayout
log4j.appender.testAppender.layout.ConversionPattern=%5p %-4# - %m%n
log4j.appender.testAppender.layout.ExtendedStackTrace=true

or

    <layout class="org.apache.log4j.PatternLayout">
      <param name="ExtendedStackTrace" value="true"/>
    </layout>

I'd really rather it be enabled by default but figured that might need to wait for a major version change
Comment 8 Paul Smith 2008-09-03 15:35:21 UTC
This looks really good James!  My only question is with regards to the extra methods in ThrowableInformation that are marked as protected, is there a need to keep them protected rather than make them private?  I can't think of a reason to expose those methods in the public api, that's not to say  there isn't one, and certainly with only 1 coffee this morning I may just be blind.

I think this is a really useful addition.
Comment 9 Curt Arnold 2008-09-03 21:54:41 UTC
The EnhancedPatternLayout in the extras (backported from log4j 1.3's PatternLayout) already has some support for configuration of stack traces by using the %throwable pattern specifier.  You can already use %throwable{full} and %throwable{short} to specify the JDK generated stack trace or just the throwable's message, respectively.  Adding support for {enhanced} and {none} (to suppress stack trace) would be fairly straight forward and could use JDK 1.4's getStackTrace().

Not sure how difficult that approach would be to add to log4j 1.2's PatternLayout since its parser wasn't designed for longer pattern specifiers.
Comment 10 James Strachan 2008-09-04 00:33:05 UTC
Paul, feel free to make those methods private if you like; I don't have a strong opinion either way :)

Curt - if you wanna add support in the EnhancedPatternLayout please be my guest too; it should be pretty trivial either to reuse the same code on ThrowableInformation, or use JDK
1.4's getStackTrace() - as Paul said, the JDK has hard coded "at " so its no biggie either way really. 

I'm keen to ensure the core log4j package has support for this enhanced stack trace feature ASAP as its what most users seem to use. Until this thread, I'd never heard of or seen the apache-log4j-extras stuff :). But the more places that support this feature in the Java logging ecosystem, the better!
Comment 11 Curt Arnold 2008-09-04 10:15:50 UTC
I've thought a little bit more of this on the drive back home and hope to look at the issue in detail in the next 24 hours.  PatternLayout or EnhancedPatternLayout probably isn't the appropriate place for the enhancement since it may be in a totally different environment that the original caller.  For example, if the LoggingEvent + ThrowableInfo has been serialized and sent to Chainsaw over a SocketAppender, you'd get the jar or version of the class in Chainsaw's environment.

I'd leaning more toward trying to mimic the ObjectRenderer approach and allow you to either register a ThrowableRenderer class through a system property or configuration file.  Something like:

java -Dlog4j.ThrowableRenderer=org.apache.log4j.EnhancedThrowableRenderer

The ObjectRenderer interface could be used for the ThrowableRenderer, but a new interface would likely be better.

I'm guessing Paul was decompiling his JVM's implementation of Throwable.printStackTrace either explicitly or implicitly through a debugger.  Different versions of the class library implemented printStackTrace differently (we had some tests fail due to slight differences in JRockit's and GCJ's implementation of printStackTrace).  It is good to know that "at" appears to be fixed, but users could still override an exception's printStackTrace() and confuse the trace parsing.  Using getStackTrace would be more reliable, but would require JDK 1.4.  Specifying the throwable renderer as a class would allow the user to customize the behavior if they ran into that type of problem. 
Comment 12 Paul Smith 2008-09-04 15:32:48 UTC
(In reply to comment #11)
> I've thought a little bit more of this on the drive back home and hope to look
> at the issue in detail in the next 24 hours.  PatternLayout or
> EnhancedPatternLayout probably isn't the appropriate place for the enhancement
> since it may be in a totally different environment that the original caller. 
> For example, if the LoggingEvent + ThrowableInfo has been serialized and sent
> to Chainsaw over a SocketAppender, you'd get the jar or version of the class in
> Chainsaw's environment.
> 

This is technically true.  The common case though is for the local appender to benefit from it.  If we added a property to PatternLayout as James has done, it can be documented with the fact that the rendered string is only relevant to local environments.

> I'd leaning more toward trying to mimic the ObjectRenderer approach and allow
> you to either register a ThrowableRenderer class through a system property or
> configuration file.  Something like:
> 
> java -Dlog4j.ThrowableRenderer=org.apache.log4j.EnhancedThrowableRenderer
> 
> The ObjectRenderer interface could be used for the ThrowableRenderer, but a new
> interface would likely be better.

I'm not sure how this gets around your Chainsaw scenario at all, doesn't this suffer from the same problem?  Anyway, I think this sort of problem just needs to be documented.  Unless the serialized form of the ThrowableInformation can carry with it all the details of the classes at computation time so that it can be displayed on some remote end.  That would change the payload weight of that class significantly though.  I'm not sure that is going to be worth the cost/effort.

> 
> I'm guessing Paul was decompiling his JVM's implementation of
> Throwable.printStackTrace either explicitly or implicitly through a debugger. 
> Different versions of the class library implemented printStackTrace differently
> (we had some tests fail due to slight differences in JRockit's and GCJ's
> implementation of printStackTrace).  It is good to know that "at" appears to be
> fixed, but users could still override an exception's printStackTrace() and
> confuse the trace parsing.  Using getStackTrace would be more reliable, but
> would require JDK 1.4.  Specifying the throwable renderer as a class would
> allow the user to customize the behavior if they ran into that type of problem. 
 

I had always thought the Layout was responsible for emitting the Throwable string, but as I learnt yesterday working on Pinpoint that that's not actually correct.  That felt odd to me.  Really the Layout should be responsible for outputting the Throwable in it's presentation form (if needed), but obviously log4j's design, right or wrong, now prohibits that approach.

Having a ThrowableRenderer is actually probably the best of all worlds.  It would be nice to have the Configurators support this new property (ala log4j.debug), and even nicer if it didn't have to specify a full class name (log4j.useSpiffyExceptionFormat which uses a known default class).
Comment 13 Curt Arnold 2008-09-04 21:08:26 UTC
From comment #12

>I'm not sure how this gets around your Chainsaw scenario at all, doesn't this
>suffer from the same problem?  Anyway, I think this sort of problem just needs
>to be documented.  Unless the serialized form of the ThrowableInformation can
>carry with it all the details of the classes at computation time so that it can
>be displayed on some remote end.  That would change the payload weight of that
>class significantly though.  I'm not sure that is going to be worth the
>cost/effort.

AsyncAppender and the SocketAppenders call LoggingEvent.getThrowableStrRep() before queuing the logging event or sending it across the wire.  The serialized form of the ThrowableInfo only contains the resulting string representation of the throwable.  Any configured ThrowableRenderer would occur in this step which would be on the thread doing the logging and not in the dispatching thread or deserializing environment.

>I had always thought the Layout was responsible for emitting the Throwable
>string, but as I learnt yesterday working on Pinpoint that that's not actually
>correct.  That felt odd to me.  Really the Layout should be responsible for
>outputting the Throwable in it's presentation form (if needed), but obviously
>log4j's design, right or wrong, now prohibits that approach.

The log4j 2.0 two pass approach of an extract phase during the call to extract value objects followed by a render phase, likely deferred, that only works on the extracted value objects should allow arbitrary formatting of the Throwable.  However, the log4j 1.2 design limits the layout to working with the output of ThrowableInfo.getThrowableStrRep. 

>Having a ThrowableRenderer is actually probably the best of all worlds.  It
>would be nice to have the Configurators support this new property (ala
>log4j.debug), and even nicer if it didn't have to specify a full class name
>(log4j.useSpiffyExceptionFormat which uses a known default class).

Could prepend "org.apache.log4j." if Class.forName() can't find the class, so you could do either

log4j.ThrowableRenderer=org.apache.log4j.SpiffyExceptionRenderer

or

log4j.ThrowableRenderer=SpiffyExceptionRenderer

The ObjectRenderer classes are in org.apache.log4j.or, I guess we could add "org.apache.log4j.tr".  However, abbreviations in package names aren't desirable and adding three more classes to org.apache.log4j doesn't seem like a big deal.
Comment 14 Ceki Gulcu 2008-09-05 08:55:42 UTC
James Strachan has kindly contributed his patch to the logback project as well. See http://jira.qos.ch/browse/LBGENERAL-23

After spending several days working on this problem, I discovered that a one line change makes a big impact on performance.

Replacing

  URL resource = type.getClassLoader().getResource(  \
                  type.getName().replace('.', '/') + ".class");
with
    
  URL resource = type.getProtectionDomain().getCodeSource().getLocation();

My tests show 12 fold improvement in performance. The time it takes to handle a stack trace goes down from 5 milliseconds to 400 microseconds. The same code without James' patch, that is without package version extraction, takes 100 microseconds. 

HTH,
Comment 15 Curt Arnold 2008-09-19 20:36:49 UTC
Committed an implementation in rev 697315.  Implementation supports ThrowableRenderer's in a fashion somewhat similar to ObjectRenderers.  Two ThrowableRenderer's are provided: org.apache.log4j.DefaultThrowableRenderer which implements the existing behavior and EnhancedThrowableRenderer which outputs code source location and version when running on JDK 1.4 or later or falls back to the existing behavior on JDK 1.3 and earlier.

DOMConfigurator and PropertyConfigurator have been modified to support configuring ThrowableRenderer's.  Add

log4j.throwableRenderer=org.apache.log4j.EnhancedThrowableRenderer

or

<throwableRenderer class="org.apache.log4j.EnhancedThrowableRenderer"/>

to log4j.properties or log4j.xml respectively.

EnhancedThrowableRenderer avoids writing and parsing the output of Throwable.printStackTrace which could potentially offset some of the performance hit of getting the source location and version.
Comment 16 Thorbjørn Ravn Andersen 2008-10-21 01:06:34 UTC
In addition to this information, it would be really nice for us to have the timestamp of the jarfile printed too.