Implement source location matching for weave messages in XML tests

[kriegaex]

In internal AspectJ integration tests, it is possible to match log messages for file and line number information in error, warning and lint messages. For weave messages, however, matching is not implemented.

[kriegaex]

@aclement, the PR review request relates to my recent Slack message, which I am quoting here in order to document my intent and the options we have for implementing this functionality:

I like to have your opinion: At first, I was wondering why filtering weave messages by line number and/or file name in AJC XML test configs was not working. Then I realised that WeaveMessage simply does not have the necessary fields.

So I extended our infrastructure a bit. My local solution now maps file/line XML values to the woven location and a new pair aspectFile, aspectLine to the corresponding source location in the aspect (e.g. advice). The information is there anyway everywhere we create instances of WeaveMessage. But currently, we only map the corresponding file/line infos into the weaver messages via string concatenation, we do not pass it into IMessage as ISourceLocation. My current solution does that, passing through the weaving target to the super constructor's (Message) sourceLocation parameter and the aspect as a 1-element ISourceLocation[] to extraSourceLocations. This has the effect of both also being displayed during compilation, which previously did not happen. When matching XML parameters, I am fetching file and line infos from those source locations. This works nicely and looks like this on the console:

[weaveInfo 1] weaveinfo at \Application.java:4::67 Join point 'method-execution(void Application.greet(java.lang.String))' in Type 'Application' (Application.java:4) advised by around advice from 'SecondAspect' (SecondAspect.java:8)
  	see also: C:\temp\ajcSandbox\AspectJ\ajcTest11973501710728944725.tmp\SecondAspect.java:8::227
[weaveInfo 2] weaveinfo at \Application.java:4::67 Join point 'method-execution(void Application.greet(java.lang.String))' in Type 'Application' (Application.java:4) advised by before advice from 'FirstAspect' (first-aspect.jar!FirstAspect.class(from FirstAspect.java))
  	see also: C:\temp\ajcSandbox\AspectJ\ajcTest11973501710728944725.tmp\first-aspect.jar!\FirstAspect.class::0

Before my changes, it would have looked like this:

[weaveInfo 1] weaveinfo at Join point 'method-execution(void Application.greet(java.lang.String))' in Type 'Application' (Application.java:4) advised by around advice from 'SecondAspect' (SecondAspect.java:8)
[weaveInfo 2] weaveinfo Join point 'method-execution(void Application.greet(java.lang.String))' in Type 'Application' (Application.java:4) advised by before advice from 'FirstAspect' (first-aspect.jar!FirstAspect.class(from FirstAspect.java))

The "see also" part is the aspect source location in this case.

Now here are my questions:

1. Does this kind of logging (which we get for free, because it works like that for other errors or warnings already) disrupt any IDE tools (AJDT?), or do the latter match on ISourceLocation meta data rather than on console log messages anyway?
2. Do you think that for weaving messages this kind of output is "too much", because the relevant infos, albeit less precise, are already baked into the weaving messages themselves?

If you think we should keep the current output, I can change the code to rather store the file, aspectFile, line, aspectLine meta data in local Message members instead of passing on ISourceLocations and access them from WeaveMessage for XML test spec matching. Everything would look like before, only matching would be improved at the cost of two extra fields in Message.

WDYT?

[kriegaex]

Andy said on Slack:

Is it weird that the first location is \Application.java when the see also location is a full path.

I replied:

That thing with the first location is a good catch. I will look into it at some point. Actually, I do not like the

first-aspect.jar!\FirstAspect.class::0

either for aspects in JARs, while there seems to be more exact info available, see

first-aspect.jar!FirstAspect.class(from FirstAspect.java)

right in the weaver message. There might be more precise source code line info available, too. I have to look into the places where the source locations are assembled.

[kriegaex]

Is it weird that the first location is \Application.java when the see also location is a full path.

@aclement, this is because in this example post-compile weaving is used and Application.java is actually from a JAR and on the inpath. The backslash character comes from the default (empty) package name.

aspectj/org.aspectj.matcher/src/main/java/org/aspectj/weaver/AbstractReferenceTypeDelegate.java

Lines 76 to 89 in 49cb924

	public final void setSourcefilename(String sourceFileName) {
	sourcefilename = sourceFileName;
	if (sourceFileName != null && sourceFileName.equals(AbstractReferenceTypeDelegate.UNKNOWN_SOURCE_FILE)) {
	sourcefilename = "Type '" + getResolvedTypeX().getName() + "' (no debug info available)";
	} else {
	String pname = getResolvedTypeX().getPackageName();
	if (pname != null) {
	sourcefilename = pname.replace('.', '/') + '/' + sourceFileName;
	}
	}
	if (sourcefilename != null && sourceContext instanceof SourceContextImpl) {
	((SourceContextImpl) sourceContext).setSourceFileName(sourcefilename);
	}
	}

This can be ameliorated by changing if (pname != null) to if (pname != null && !pname.isEmpty()), yielding Application.java for the name and also first-aspect.jar!FirstAspect.class instead of first-aspect.jar!\FirstAspect.class. I think, this cosmetic change makes sense. I could also here

aspectj/weaver/src/main/java/org/aspectj/weaver/bcel/BcelObjectType.java

Line 166 in 1c487b2

setSourcefilename(javaClass.getSourceFileName());

simply call setSourcefilename(javaClass.getFileName()); instead, which would yield something like this:

[weaveInfo 1] weaveinfo at C:\temp\ajcSandbox\AspectJ\ajcTest679061309717043359.tmp\Application.class:4::67 Join point 'method-execution(void Application.greet(java.lang.String))' in Type 'Application' (Application.class:4) advised by around advice from 'SecondAspect' (SecondAspect.java:8)
  	see also: C:\temp\ajcSandbox\AspectJ\ajcTest679061309717043359.tmp\SecondAspect.java:8::227
[weaveInfo 2] weaveinfo at C:\temp\ajcSandbox\AspectJ\ajcTest679061309717043359.tmp\Application.class:4::67 Join point 'method-execution(void Application.greet(java.lang.String))' in Type 'Application' (Application.class:4) advised by before advice from 'FirstAspect' (first-aspect.jar!FirstAspect.class(from FirstAspect.class))
  	see also: C:\temp\ajcSandbox\AspectJ\ajcTest679061309717043359.tmp\first-aspect.jar!FirstAspect.class::0

On the one hand, it would be a complete path for files from JARs. OTOH, that path might be from another system and also unnecessarily expose file system info from there. OK, the data are in the class file anyway, but I think in this case they provide no added value and might even irritate more than help the user.

Feel free to comment. For now, I think I am going to leave it at the cosmetic change for default package classes, removing the leading (back)slash. For classes and aspects compiled from sources, the full paths are already there in weaving messages.

[kriegaex]

when the see also location is a full path

Hm, I am just reconsidering this. You are right, the "see also" location is also a path to a class file, even from inside a JAR.

[kriegaex]

For the record: I have experimented with variations of code like this:

final String fileName = javaClass.getFileName();
final String sourceFileName = javaClass.getSourceFileName();
if (fileName == null || !fileName.endsWith(".class"))
  setSourcefilename(sourceFileName);
else if (sourceFileName == null || sourceFileName.isEmpty() || sourceFileName.endsWith(".class"))
  setSourcefilename(fileName);
else
  setSourcefilename(fileName + " (from " + sourceFileName + ")");

But this leads to unwanted ripple effects with certain types of output. E.g., it could look like this:

... advised by before advice from 'FirstAspect' (first-aspect.jar!FirstAspect.class (from FirstAspect.class (from FirstAspect.class (from FirstAspect.java)))

The simple variant

setSourcefilename(javaClass.getFileName())

would lead to (single line, line breaks added manually) :

weaveinfo at C:\temp\ajcSandbox\AspectJ\ajcTest4315460611977815268.tmp\Application.class:4::67
  Join point 'method-execution(void Application.greet(java.lang.String))'
  in Type 'Application' (Application.class:4)
  advised by around advice from 'SecondAspect' (SecondAspect.java:8)

Things like Application.class:4::67 or Application.class:4 also look strange. So for now, I am not going to change source file representation for post-compile weaving *.class files, even though in theory it would be possible to synthesise perfect messages everywhere. But that would require more work in different parts of the code, which I am not willing to invest now. We have an improvement already, hopefully good enough to merge.

[kriegaex]

It looks as if removing the leading file separator also has unwanted side effects, e.g. it makes Ajc164Tests::testItdsAspectPathModel_pr265729_1 fail as follows:

<root>  [java source file] 
  demo  [package] 
    Orange.java  [java source file] C:\temp\ajcSandbox\AspectJ\ajcTest530306528813709598.tmp\Orange.java:1::0
      demo  [package declaration] C:\temp\ajcSandbox\AspectJ\ajcTest530306528813709598.tmp\Orange.java:1::8
        [import reference] 
      Orange  [class] C:\temp\ajcSandbox\AspectJ\ajcTest530306528813709598.tmp\Orange.java:3::30
    Strawberry.java  [java source file] C:\temp\ajcSandbox\AspectJ\ajcTest530306528813709598.tmp\Strawberry.java:1::0
      demo  [package declaration] C:\temp\ajcSandbox\AspectJ\ajcTest530306528813709598.tmp\Strawberry.java:1::8
        [import reference] 
      Strawberry  [class] C:\temp\ajcSandbox\AspectJ\ajcTest530306528813709598.tmp\Strawberry.java:3::30
    Fruit.java  [java source file] C:\temp\ajcSandbox\AspectJ\ajcTest530306528813709598.tmp\Fruit.java:1::0
      demo  [package declaration] C:\temp\ajcSandbox\AspectJ\ajcTest530306528813709598.tmp\Fruit.java:1::8
        [import reference] 
      Fruit  [class] C:\temp\ajcSandbox\AspectJ\ajcTest530306528813709598.tmp\Fruit.java:2::28
  binaries  [source folder] 
      [package] 
      library.jar!Aspect.class  [file] C:\temp\ajcSandbox\AspectJ\ajcTest530306528813709598.tmp\library.jar!Aspect.class:1::0
        Aspect  [aspect] C:\temp\ajcSandbox\AspectJ\ajcTest530306528813709598.tmp\library.jar!Aspect.class:1::0
          Orange.getColor()  [inter-type method] C:\temp\ajcSandbox\AspectJ\ajcTest530306528813709598.tmp\library.jar!Aspect.class:5::0
          Strawberry.color  [inter-type field] C:\temp\ajcSandbox\AspectJ\ajcTest530306528813709598.tmp\library.jar!Aspect.class:6::0
          Fruit.Fruit(java.awt.Color,java.lang.String)  [inter-type constructor] C:\temp\ajcSandbox\AspectJ\ajcTest530306528813709598.tmp\library.jar!Aspect.class:7::0

junit.framework.ComparisonFailure: 
Expected :/binaries<(Aspect.class>Aspect°Orange.getColor
Actual   :/binaries<(library.jar!Aspect.class>Aspect°Orange.getColor

I do not feel so inclined to investigate how to fix that in AJDT and check for side effects there when working with AJDT in Eclipse. Sigh - I am going to revert the change, and users will have to live with \Application.java style source paths for default package classes.