Bug 303924 - @DeclareMixins are reweaved with random effects: correctly, not at all or partially (the delegating methods are added but not the implements)
Summary: @DeclareMixins are reweaved with random effects: correctly, not at all or par...
Status: RESOLVED FIXED
Alias: None
Product: AspectJ
Classification: Tools
Component: Compiler (show other bugs)
Version: 1.6.7   Edit
Hardware: PC Linux
: P2 major (vote)
Target Milestone: 1.6.9M1   Edit
Assignee: aspectj inbox CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-02-25 11:00 EST by Frank Pavageau CLA
Modified: 2010-04-16 13:10 EDT (History)
1 user (show)

See Also:


Attachments
Sample aspects (1.02 KB, application/x-gzip)
2010-02-25 11:05 EST, Frank Pavageau CLA
no flags Details
Weaving logs (75.24 KB, application/x-gzip)
2010-02-25 11:09 EST, Frank Pavageau CLA
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Frank Pavageau CLA 2010-02-25 11:00:04 EST
Build Identifier: 1.6.7, 1.6.8, 1.6.9-20100224133816

Following the mail I sent to aspectj-users (http://dev.eclipse.org/mhonarc/lists/aspectj-users/msg11782.html), I'm not sure it's related to https://bugs.eclipse.org/bugs/show_bug.cgi?id=302460. I'm opening this bug to follow the problem independently.

In summary, I have a multi-module maven project:
 - in module1, I have @Aspects with @DeclareMixin and @Before weaved on some classes
 - in module2, I have another @Aspect with pointcuts on module1 and module2 classes

With AspectJ 1.6.6, everything works fine. With 1.6.7, 1.6.8 or the daily build of 1.6.9, the results of the reweaving of module1's @Aspects on module1's classes during the module2 build are random:
 - it works fine rarely
 - sometimes, the mixing does not happen at all but the weaved advices have runtime tests, meaning they never execute
 - sometimes, the mixing does not happen at all but some of the weaved advices have runtime tests, some don't, resulting in a ClassCastException
 - sometimes, the mixing happens partially (the delegating methods are added, but the class does not actually implement the interface) and the weaved advices don't have runtime tests, resulting in an IncompatibleClassChangeError

So, without actually knowing the internals of AspectJ, I feel it might be related to a cache problem as is suspected in bug 302460, but it's really a baseless gut feeling... It doesn't really seem to be an order problem, since the order of the weaving is really consistent from run to run in the logs.

Reproducible: Sometimes
Comment 1 Frank Pavageau CLA 2010-02-25 11:05:40 EST
Created attachment 160200 [details]
Sample aspects

I cannot extract a testcase from my project at the moment, there's always a point where by removing an irrelevant class, everything starts working nicely again. However, here are the @Aspects with @DeclareMixin I have, to illustrate the problem.
Comment 2 Frank Pavageau CLA 2010-02-25 11:09:33 EST
Created attachment 160201 [details]
Weaving logs

This tar.gz contains the log (verbose + showWeavingInfo) of the initial weaving (in module1), as well as the log of the reweaving (in module2) run 5 times in a row with AspectJ 1.6.8 then 1.6.9 build 20100224133816, to illustrate the randomness of the weaving.
Comment 3 Frank Pavageau CLA 2010-02-25 11:12:02 EST
I'm not giving up on creating an almost reproducible testcase yet, but it does seem tricky.
Comment 4 Andrew Clement CLA 2010-02-25 12:44:37 EST
Are you able to simply share the full project with me? (Send it to me via email)  I have no idea what the problem is here, meaning that without a testcase of some form it is going to take a while to resolve - whereas with a recreateable scenario I can fix it in < 24hours.
Comment 5 Andrew Clement CLA 2010-03-02 19:29:25 EST
I'm trying to puzzle through what is causing this.

On the secondary build we don't see these important messages:

[INFO] Mixing interface 'com.sfr.ecat.core.graph.PersistenceStatus' (PersistenceStatusAspect.java) into type 'com.sfr.ecat.core.model.Entity' (Entity.java)
[INFO] Mixing interface 'com.sfr.ecat.core.util.Lockable' (LockableAspect.java) into type 'com.sfr.ecat.core.model.Entity' (Entity.java)
[INFO] Type 'com.sfr.ecat.core.model.Entity' (Entity.java) has intertyped method..
[INFO] Type 'com.sfr.ecat.core.model.Entity' (Entity.java) has intertyped method.. 
[INFO] Type 'com.sfr.ecat.core.model.Entity' (Entity.java) has intertyped method.. 
[INFO] Type 'com.sfr.ecat.core.model.Entity' (Entity.java) has intertyped method.. 

Which manifest from the @DeclareMixin and related methods from the mixed in interface implementation.

It is not surprising to see all the weave info message change to require a runtime-test when the mixin messages are missing as the runtime test is checking what would have been confirmed at weave time if the mixin had applied.

The fact that we don't see them possibly suggests one of:

(1) the aspect isn't being found on the secondary weave and so isn't participating in the weaving process
(2) the target for the match (Entity) isn't being processed and so the aspect isn't being matched against it
(3) a match is being attempted but it looks like the type already has the parent so there is no weaving message.

Now, we can see elsewhere in the failing logs that advice is being applied from the LockableAspect and PersistenceStatusAspect - so the problem cannot be (1)

We can also see advice being applied to the Entity type methods in the logs, so it can't be (2).

That leaves (3).  However, as the woven code actually fails, it shows there is some conflict - if the ITDs/mixin don't match because it already has them, why does the weaver start introducing runtime tests later.  Surely the check for whether a runtime test was necessary should also have found out that Entity has the mixin.

The next step is probably to collect some targetted debug info, we need to know: is an attempt made to match the Mixin and ITDs against the Entity type? if so, what is the result?
Comment 6 Andrew Clement CLA 2010-03-03 14:28:59 EST
as I thought, it was (3).  Since 1.6.6 a few extra caches are in place - and the one causing this issue was in BcelObjectType.  The set of interfaces implemented by a type was cached in a weak reference.  If the cache happened to be populated before reweaving started then when reweaving undid the effect of the mixin, this change wouldn't get noticed by the BcelObjectType cache.  What happens after that is based on 'luck' - basically whether the weak reference gets cleared due to a GC before someone calls it and relies on the result.  If a GC has occurred the weak reference is cleared and the cache will rebuild correctly.  If the GC has not occurred, the weak reference will make it look like Entity implements the mixed in interfaces when it does not.

I think the solution to this will also fix the other bug.

Fix committed, will be in a dev build shortly.  thanks to Frank for sharing his code with me, enabling me to find the problem.
Comment 7 Andrew Clement CLA 2010-03-03 23:04:50 EST
dev build containing the proposed fix is now available.
Comment 8 Frank Pavageau CLA 2010-03-04 05:26:58 EST
I've built the project a dozen times with last night's development build and it hasn't failed once, so I can confirm that everything's working fine on my side.

Thanks Andy!
Comment 9 Andrew Clement CLA 2010-03-04 11:09:55 EST
fixed! thanks for confirming.