Bug 231945 - [plan] [ltw] NullPointerException at WeavingAdaptor.weaveClass on misc. classes
Summary: [plan] [ltw] NullPointerException at WeavingAdaptor.weaveClass on misc. classes
Status: RESOLVED WONTFIX
Alias: None
Product: AspectJ
Classification: Tools
Component: LTWeaving (show other bugs)
Version: 1.6.0   Edit
Hardware: Macintosh Mac OS X - Carbon (unsup.)
: P1 normal (vote)
Target Milestone: 1.6.3   Edit
Assignee: aspectj inbox CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2008-05-13 17:20 EDT by Ian Brandt CLA
Modified: 2008-12-02 19:23 EST (History)
1 user (show)

See Also:


Attachments
Core dump. (12.75 KB, text/plain)
2008-05-13 17:20 EDT, Ian Brandt CLA
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Ian Brandt CLA 2008-05-13 17:20:55 EDT
Created attachment 100060 [details]
Core dump.

Tomcat 6.0.16, Spring 2.5.4 with TomcatInstrumentableClassLoader for LTW, and AspectJ 1.6.0 final.  Getting core dumps on shutdown.  Repeats several times and the core dumps all look about the same.  A representative one is attached.

There are some extra log messages that accompany each dump and seem to inform on the classes in question.  The apparently associated Jars are: jetty-6.1.7.jar, jdom-1.0.jar and dom4j-1.6.1.jar.

May 13, 2008 10:29:20 AM org.aspectj.weaver.tools.Jdk14Trace error
SEVERE: org/mortbay/io/nio/NIOBuffer
java.lang.NullPointerException
	at org.aspectj.weaver.tools.WeavingAdaptor.weaveClass(WeavingAdaptor.java:252)
[...]

May 13, 2008 10:29:20 AM org.aspectj.weaver.tools.Jdk14Trace error
SEVERE: org/mortbay/jetty/HttpException
java.lang.NullPointerException
	at org.aspectj.weaver.tools.WeavingAdaptor.weaveClass(WeavingAdaptor.java:252)
[...]

May 13, 2008 10:29:20 AM org.aspectj.weaver.tools.Jdk14Trace error
SEVERE: org/mortbay/io/nio/SelectChannelEndPoint$IdleTask
[...]

May 13, 2008 10:29:20 AM org.aspectj.weaver.tools.Jdk14Trace error
SEVERE: org/jdom/IllegalDataException
[...]

May 13, 2008 10:29:20 AM org.aspectj.weaver.tools.Jdk14Trace error
SEVERE: org/jdom/IllegalTargetException
[...]

May 13, 2008 10:29:20 AM org.aspectj.weaver.tools.Jdk14Trace error
SEVERE: org/dom4j/io/DispatchHandler
[...]

May 13, 2008 10:29:20 AM org.aspectj.weaver.tools.Jdk14Trace error
SEVERE: org/springframework/context/annotation/CommonAnnotationBeanPostProcessor$ResourceDependencyDescriptor
[...]
Comment 1 Andrew Clement CLA 2008-05-13 19:27:04 EDT
the error is occurring on a line of code that produces trace - it looks like the trace object being asked if trace is on is null.  This is set via static and i can't immediately see how it ended up being null.
Comment 2 Andrew Clement CLA 2008-05-14 12:08:50 EDT
Are you able to confirm if these are regressions - did everything used to work fine with this code and Spring2.5.3/AspectJ1.5.4? I'm going to ask the same in the other bug of yours :)
Comment 3 Ian Brandt CLA 2008-05-14 15:52:23 EDT
(In reply to comment #2)
> Are you able to confirm if these are regressions - did everything used to work
> fine with this code and Spring2.5.3/AspectJ1.5.4? I'm going to ask the same in
> the other bug of yours :)
> 

CC from bug #231941:

I don't believe so.  I was on 2.5.3/1.5.4 and switched from JBoss to straight Tomcat.  At the same time I switched from the 2.5.3 spring-agent to the 2.5.3 spring-tomcat-weaver.  This is when the core dumps first manifested, on 2.5.3/1.5.4, so I upgraded  everything to 2.5.4/1.6.0.  A spring-tomcat-weaver message about a missing aop.xml disappeared on the upgrade, but otherwise the cores persisted.
Comment 4 Andrew Clement CLA 2008-06-11 18:26:09 EDT
you mentioned in the other bug you were setup for debugging this now - are you able to determine if trace is null when this goes wrong?

If you have the full stack trace, do you see it looping round and re-entering weaveClass after being in it earlier in the stack? I'm wondering if in some way the initialization of the trace field is coming back into weaveClass() (when it shouldn't) and leading to an NPE.
Comment 5 Ian Brandt CLA 2008-07-07 20:48:45 EDT
(In reply to comment #4)
> you mentioned in the other bug you were setup for debugging this now - are you
> able to determine if trace is null when this goes wrong?
> 
> If you have the full stack trace, do you see it looping round and re-entering
> weaveClass after being in it earlier in the stack? I'm wondering if in some way
> the initialization of the trace field is coming back into weaveClass() (when it
> shouldn't) and leading to an NPE.
> 

Apologies for my long hiatus on this bug.

The static trace variable is the null, causing the exception.  It does not appear that recursive entry into weaveClass is the issue, though I believe I have found the culprit.  I was examining the stack trace in the previously attached core and noticed the following lines:

	at org.apache.catalina.loader.WebappClassLoader.clearReferences(WebappClassLoader.java:1600)
	at org.apache.catalina.loader.WebappClassLoader.stop(WebappClassLoader.java:1497)

It looks like the clearReferences is the culprit.  Implementation for the version I'm using is at http://svn.apache.org/repos/asf/tomcat/tc6.0.x/tags/TOMCAT_6_0_16/java/org/apache/catalina/loader/WebappClassLoader.java.

I've confirmed that it does clear the trace variable on org.aspectj.weaver.tools.WeavingAdaptor.

So the flow appears to be:

1) Initiate Tomcat Shutdown
2) Tomcat clears out references including private static ones on all the classes it's loaded (i.e. WeavingAdaptor.trace).
3) In the process of doing so it triggers a new class to be loaded.
4) That in turn fires off weaving via org.springframework.instrument.classloading.tomcat.TomcatInstrumentableClassLoader.findResourceInternal.
5) As the weaver has been invalidated earlier in the clearReferences loop the weave fails on the NPE.
Comment 6 Ian Brandt CLA 2008-11-12 20:27:42 EST
Just FYI I've upgraded to Tomcat 6.0.18 and Spring 2.5.6, but no change.

Is this bug something I should take up with the Tomcat folks, or do you think it's reasonable for AspectJ or Springs TomcatInstrumentableClassLoader to work around the scenario in my Comment #5?
Comment 7 Andrew Clement CLA 2008-12-02 17:56:29 EST
sorry i'm slow getting to this.

That is a good find. I think AspectJ could work around it.  I'm just not sure what the workaround should be.  Options seem to be:

- recreate the trace object if it gets trashed.
- treat a null object as 'trace is off'.
- don't continue weaving if we discover that has been nulled.

The safest would probably be the final option - since I don't know what other state it may have damaged elsewhere in the weaver (other trace vars), so if I simply coped with null here we may fail later where it has damaged another class.  Do you think you will need things to be woven correctly on a shutdown?  What is the new class that it attempts to load on shutdown? an application one or?
Comment 8 Ian Brandt CLA 2008-12-02 18:50:51 EST
(In reply to comment #7)

What a difference a day makes...  I'm not sure why I didn't notice this before, but WebappClassLoader.clearReferences() is configurable.  I just added the following to my VM arguments when launching Tomcat:

-Dorg.apache.catalina.loader.WebappClassLoader.ENABLE_CLEAR_REFERENCES=false

I now get a clean shutdown with no ajcores.

As the comment in clearReferences says, the encapsulation violating reference nuke was to work around potential GC bugs.  I'm generally restarting or shutting down Tomcat as needed, not reloading webapps, hence I'm not much worried about memory leaks.  As such this workaround fulfills my immediate use case.  A solution may still be needed here, but the more I think about the more it seems not something AspectJ should have to worry about.  Perhaps TomcatInstrumentableClassLoader can detect the shutting down state and no-op?   I'll leave it to you to mark this a WONTFIX or not.

More inline...

> Do you think you will need things to be woven correctly on a shutdown?

I don't have and can't think of a need for weaving during shutdown, but that's just me.

> What is the new class that it attempts to load on shutdown? an application one
> or?

From the log it appears ajcores are dumped for:

SEVERE: org/mortbay/io/nio/NIOBuffer
SEVERE: org/mortbay/jetty/HttpException
SEVERE: org/mortbay/io/nio/SelectChannelEndPoint$IdleTask
SEVERE: org/jdom/IllegalDataException
SEVERE: org/jdom/IllegalTargetException
SEVERE: org/dom4j/io/DispatchHandler
SEVERE: org/springframework/context/annotation/CommonAnnotationBeanPostProcessor$LookupDependencyDescriptor

Looks like it might be ancillary references being loaded along the path of my webapp's Spring context shudown cycle (the context manages an embedded Jetty instance used as a localhost bound back door admin interface).
Comment 9 Andrew Clement CLA 2008-12-02 19:23:48 EST
Thanks Ian.  I think I'll mark this WONTFIX right now - just so my TODO list is shorter :)  I do see the tomcat guys now and again so I will try and remember to talk to them about this.  I guess I'm surprised I haven't seen more people complaining about this issue.  Thankfully you have included the settings in your comment so any capable googler will be able to discover what they need to do.