Comment 1 Andrew Clement 2018-10-11 00:42:01 EDT

I am trying to recreate this but not having much luck. I try building master of spf4j but always get one problem or another. Same thing if I try a tag like 8.5.4. Building with:

mvn -Dgpg.skip=true clean install

Except i don't see the exception from here.  Should I be seeing it right now if I build master?

Comment 2 Zoltan Farkas 2018-10-17 14:09:56 EDT

To give a bit more context:

I am building with Oracle JDK 1.8.0_u181 on macosx mojave.

Interestingly when running with JDK 11 these errors are not being logged...

Comment 3 Zoltan Farkas 2018-11-25 09:15:59 EST

Andrew, I believe the errors are happening with JDK 1.8 only. Are you able to reproduce>?

Comment 4 Zoltan Farkas 2019-01-01 09:24:54 EST

It also looks like on Linux this issue does not manifest on:

Java version: 1.8.0_151, vendor: Oracle Corporation
Java home: /usr/lib/jvm/java-8-oracle/jre
Default locale: en_US, platform encoding: UTF-8
OS name: "linux", version: "4.4.0-98-generic", arch: "amd64", family: "unix"

However the Issue still manifests itself on MacOSX 10.14.2 (mojave) with Oracle JDK jdk1.8.0_192...

Comment 5 Andrew Clement 2019-01-14 18:37:53 EST

Finally I managed to recreate the problem, yey. Think these were my precise steps (I am on mojave jdk1.8.0_192):

git clone git@github.com:zolyfarkas/spf4j.git
git checkout spf4j-8.5.25
mvn -Dgpg.skip=true clean install
cd spf4j-aspects
mvn -Dgpg.skip=true install


The problem appears to be due to jacoco altering the bytecode and breaking assumptions AspectJ likes to make. Normally the local variables that relate to the method parameters have a range from 0 to end-of-method. This looks like it would be fine because if you look at the bytecode of PerformanceMonitorAspect.performanceMonitoredMethod on disk you will see:
      LocalVariableTable:
        Start  Length  Slot  Name   Signature
           92     107    13 errorThresholdMillis   J
            0     297     0  this   Lorg/spf4j/perf/aspects/PerformanceMonitorAspect;
            0     297     1   pjp   Lorg/aspectj/lang/ProceedingJoinPoint;
            0     297     2 annot   Lorg/spf4j/annotations/PerformanceMonitor;
            4     293     3 start   J
           12     285     5 result   Ljava/lang/Object;

Jacoco at runtime inserts 4 new bytecodes but doesn't update the positioning for those slots that start at 0, so they now start at 4 (you could argue whether it should...):

LocalVariable(start_pc = 4, length = 399, index = 0:org.spf4j.perf.aspects.PerformanceMonitorAspect this)
LocalVariable(start_pc = 4, length = 399, index = 1:org.aspectj.lang.ProceedingJoinPoint pjp)
LocalVariable(start_pc = 4, length = 399, index = 2:org.spf4j.annotations.PerformanceMonitor annot)

(This is in the bytecode as AspectJ weaver sees it, so loaded off disk, modified by jacoco then AspectJ sees it).

This isn't the first occurrence of this kind of problem. There is some special handling in the code for other bytecode tools affecting things but that code didn't handle the case here, particularly because that errorThresholdMillis entry has been inserted at the start of the table. 

So I've tweaked things to more eagerly use the argNames annotation value if set (and it is set here), with these changes the messages go away but I see other problems now - can you try out my dev build and see if they are a new problem I need to look at?

The 1.9.3.BUILD-SNAPSHOT is found in this repository:

        <repository>
            <id>spring-maven-snapshot</id>
            <name>Spring Maven Snapshot Repository</name>
            <url>http://maven.springframework.org/snapshot</url>
        </repository>

To use that I had to edit the aspectj.version in the root pom, I also had to edit the javaagent string in the spf4j-aspects project because the snapshot will include a timestamp in the filename and it needs hardcoding in the agent string.

Just fyi, here are the errors I now see when running that last maven command:


[ERROR] org.spf4j.perf.aspects.PerformanceMonitorAspectTest  Time elapsed: 0.957 s  <<< FAILURE!
java.lang.AssertionError:
Failed test testPerformanceMonitoredMethod(org.spf4j.perf.aspects.PerformanceMonitorAspectTest), Expected in category: "org.aspectj.weaver.bcel" and minLevel: ERROR:
(hasProperty("message", a string matching the pattern '.*') and hasProperty("level", <ERROR>))
(hasProperty("message", a string matching the pattern '.*') and hasProperty("level", <ERROR>))
(hasProperty("message", a string matching the pattern '.*') and hasProperty("level", <ERROR>))
(hasProperty("message", a string matching the pattern '.*') and hasProperty("level", <ERROR>))
Matched 0
	at org.spf4j.test.log.junit4.Spf4jTestLogRunListenerSingleton.testFinished(Spf4jTestLogRunListenerSingleton.java:219)
	at org.spf4j.test.log.junit4.Spf4jTestLogRunListener.testFinished(Spf4jTestLogRunListener.java:51)
	at org.junit.runner.notification.SynchronizedRunListener.testFinished(SynchronizedRunListener.java:56)
	at org.junit.runner.notification.RunNotifier$7.notifyListener(RunNotifier.java:190)
	at org.junit.runner.notification.RunNotifier$SafeNotifier.run(RunNotifier.java:72)
	at org.junit.runner.notification.RunNotifier.fireTestFinished(RunNotifier.java:187)
	at org.junit.internal.runners.model.EachTestNotifier.fireTestFinished(EachTestNotifier.java:38)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:331)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)