[FIXED] Maven + AspectJ LTW [ERROR] [AppClassloader] and Joinpoint target null

Issue

I'm trying to make a simple app with Maven and AspectJ using LoadTime-Weaving.
I have an aspect which targets an annotation and calculates if the method's execution time was longer than expected. But when it gets to call getSLAAnnotation() to get the joinpoint method, it throws NullPointerException. It does return the joinpoint signature though. I beleive it might be related to the maven output I'm getting. \

[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[ERROR] [AppClassLoader@18b4aac2] info AspectJ Weaver Version 1.9.7 built on Thursday Jun 24, 2021 at 16:14:45 PDT
[ERROR] [AppClassLoader@18b4aac2] info register classloader sun.misc.Launcher$AppClassLoader@18b4aac2
[ERROR] [AppClassLoader@18b4aac2] info using configuration /D:/RFS/prueba-aspectj/target/classes/META-INF/aop-ajc.xml
[ERROR] [AppClassLoader@18b4aac2] info using configuration file:/C:/Users/MT27745023/.m2/repository/io/qameta/allure/allure-testng/2.17.2/allure-testng-2.17.2.jar!/META-INF/aop-ajc.xml
[ERROR] [AppClassLoader@18b4aac2] info register aspect aspectPackage.SLAAspect
[ERROR] [AppClassLoader@18b4aac2] info register aspect io.qameta.allure.aspects.StepsAspects
[ERROR] [AppClassLoader@18b4aac2] info register aspect io.qameta.allure.aspects.AttachmentsAspects
[INFO] Running TestSuite
[ERROR] [AppClassLoader@18b4aac2] info processing reweavable type page.StepTestPage: page\StepTestPage.java
[ERROR] [AppClassLoader@18b4aac2] info successfully verified type aspectPackage.SLAAspect exists.  Originates from aspectPackage\SLAAspect.java
[ERROR] [AppClassLoader@18b4aac2] weaveinfo Join point 'method-execution(void page.StepTestPage.pruebaStepAspect())' in Type 'page.StepTestPage' (StepTestPage.java:11) advised by before advice from 'aspectPackage.SLAAspect' (SLAAspect.java)
[ERROR] [AppClassLoader@18b4aac2] weaveinfo Join point 'method-execution(void page.StepTestPage.pruebaStepAspect())' in Type 'page.StepTestPage' (StepTestPage.java:11) advised by after advice from 'aspectPackage.SLAAspect' (SLAAspect.java)
[ERROR] [AppClassLoader@18b4aac2] weaveinfo Join point 'method-execution(void page.StepTestPage.pruebaStepAspect())' in Type 'page.StepTestPage' (StepTestPage.java:11) advised by before advice from 'io.qameta.allure.aspects.StepsAspects' (StepsAspects.java)
[ERROR] [AppClassLoader@18b4aac2] weaveinfo Join point 'method-execution(void page.StepTestPage.pruebaStepAspect())' in Type 'page.StepTestPage' (StepTestPage.java:11) advised by afterThrowing advice from 'io.qameta.allure.aspects.StepsAspects' (StepsAspects.java)
[ERROR] [AppClassLoader@18b4aac2] weaveinfo Join point 'method-execution(void page.StepTestPage.pruebaStepAspect())' in Type 'page.StepTestPage' (StepTestPage.java:11) advised by afterReturning advice from 'io.qameta.allure.aspects.StepsAspects' (StepsAspects.java)
[ERROR] [AppClassLoader@18b4aac2] info processing reweavable type aspectPackage.SLAAspect: aspectPackage\SLAAspect.java
[ERROR] [AppClassLoader@18b4aac2] info successfully verified type aspectPackage.SLAAspect exists.  Originates from aspectPackage\SLAAspect.java

The aspect:

package aspectPackage;

import java.lang.reflect.Method;

import env.EnvironmentConsumer;
import io.github.cdimascio.dotenv.Dotenv;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.After;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.reflect.MethodSignature;
import java.time.LocalTime;
import java.time.temporal.Temporal;
import java.time.Duration;
import java.time.ZonedDateTime;
import java.time.format.DateTimeFormatter;

@Aspect
public class SLAAspect{
    private DateTimeFormatter ISODateTimeFormatter = java.time.format.DateTimeFormatter.ofPattern("yyyy-MM-dd'T'HH:mm:ss.SSSZ");
    private DateTimeFormatter DurationFormatter = java.time.format.DateTimeFormatter.ofPattern("HH:mm:ss");
    ZonedDateTime dtFechaInicial;
    SLA ca;

    @Before("execution(* *(..)) && @annotation(aspectPackage.SLA)")
    public void beforeTiempos(JoinPoint jp) {
        System.out.println("BEFORE SLAASPECT");
        ca = getSLAAnnotation(jp);
        String fechaI = ZonedDateTime.now().format(ISODateTimeFormatter);
        dtFechaInicial = ZonedDateTime.parse(fechaI, ISODateTimeFormatter);
    }

    @After("execution(* *(..)) && @annotation(aspectPackage.SLA)")
    public void afterLogger(JoinPoint jp) throws Exception{
        String fechaF = ZonedDateTime.now().format(ISODateTimeFormatter);
        System.out.println("AFTER SLAASPECT");
        ZonedDateTime dtFechaFinal = ZonedDateTime.parse(fechaF,ISODateTimeFormatter);

        Duration tiempoTotal = calcularTiempoEntreFechas(dtFechaInicial,dtFechaFinal);
        System.out.println(ca.toString());
        System.out.println(ca.tiempoEsperado());

        Duration sla = Duration.ofSeconds(ca.tiempoEsperado());

        int resultSla = calcularSla (tiempoTotal, sla);
        String resultadoFormateado = LocalTime.MIDNIGHT.plus(tiempoTotal).format(DurationFormatter);
        Dotenv settings = null;
        Duration timeout = null;
        try{
            settings = EnvironmentConsumer.getInstance("settings");
            timeout = Duration.ofSeconds(Long.parseLong(settings.get("Timeout")));
        }catch(Exception e){
            System.out.println("\n\n\n\nERROR CON EL ENVIRONMENT\n\n\n\n");
            throw e;
        }

        if(resultSla != 1 && tiempoTotal.compareTo(timeout) != 0){
            throw new Exception("SLA Exception: Se excedió del tiempo esperado, el step duró: " + resultadoFormateado + " segundos");
        }else{
            throw new Exception("Step timeout");
        }
    }

    private Duration calcularTiempoEntreFechas(Temporal fechaInicial, Temporal fechaFinal) {
        // Calcula el tiempo final de ejecucion
        return Duration.between(fechaInicial, fechaFinal);
    }

    private int calcularSla(Duration tiempoT, Duration tiempoE) {
        // Calcula si tarda mas del tiempo esperados

        // System.out.println(tiempoE.compareTo(tiempoT));

        return tiempoE.compareTo(tiempoT);
    }

    private SLA getSLAAnnotation(JoinPoint joinPoint) {
        SLA ca = null;
        try {
            MethodSignature signature = (MethodSignature) joinPoint.getSignature();
            Object target = joinPoint.getTarget();
            Method method = target.getClass().
                    getMethod(signature.getMethod().getName(), signature.getMethod().getParameterTypes());

            if (method.isAnnotationPresent(SLA.class)){
                ca = method.getAnnotation(SLA.class);
            }else if (joinPoint.getTarget().getClass().isAnnotationPresent(SLA.class)){
                ca = joinPoint.getTarget().getClass().getAnnotation(SLA.class);
            }
            return ca;
        }catch(Exception e) {
            return ca;
        }
    }
}

This is the pom.xml

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>

    <groupId>ar.com.samsistemas</groupId>
    <artifactId>aspectSLADemo</artifactId>
    <version>1.0-SNAPSHOT</version>
    <properties>
        <maven.compiler.source>8</maven.compiler.source>
        <maven.compiler.target>8</maven.compiler.target>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
        <aspectj.version>1.9.7</aspectj.version>
        <allure-testng.version>2.17.2</allure-testng.version>
    </properties>

    <build>
        <plugins>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-surefire-plugin</artifactId>
                <version>3.0.0-M5</version>
                <configuration>
                    <argLine>
                         -javaagent:"${settings.localRepository}/org/aspectj/aspectjweaver/${aspectj.version}/aspectjweaver-${aspectj.version}.jar"
                    </argLine>
                    <suiteXmlFiles>
                        <suiteXmlFile>./testng.xml</suiteXmlFile>
                    </suiteXmlFiles>
                    <useSystemClassLoader>true</useSystemClassLoader>
                    <forkMode>always</forkMode>
                </configuration>
            </plugin>
        </plugins>
    </build>

    <dependencies>
        <dependency>
            <groupId>org.testng</groupId>
            <artifactId>testng</artifactId>
            <version>7.4.0</version>
            <scope>test</scope>
        </dependency>
        <dependency>
            <groupId>org.aspectj</groupId>
            <artifactId>aspectjrt</artifactId>
            <version>${aspectj.version}</version>
        </dependency>
        <dependency>
            <groupId>org.aspectj</groupId>
            <artifactId>aspectjweaver</artifactId>
            <version>${aspectj.version}</version>
        </dependency>
        <dependency>
            <groupId>io.qameta.allure</groupId>
            <artifactId>allure-testng</artifactId>
            <version>${allure-testng.version}</version>
        </dependency>
        <dependency>
            <groupId>ar.com.samsistemas</groupId>
            <artifactId>web-utils</artifactId>
            <version>0.0.1m</version>
        </dependency>

        <!-- Environment properties consumer from personal utils-->
        <dependency>
            <groupId>ar.com.samsistemas</groupId>
            <artifactId>environment-utils</artifactId>
            <version>0.0.1b</version>
        </dependency>
    </dependencies>
</project>

and the aop.xml

<aspectj>
    <aspects>
        <aspect name="aspectPackage.SLAAspect"/>
        <weaver options="-verbose -showWeaveInfo">
            <include within="*"/>
        </weaver>
    </aspects>
</aspectj>

Solution

Preface

Sorry, this is going to be a lengthy answer, because there is so much wrong or problematic with your own aspect code, I could not resist to suggest how to fix it. But we are going to do that step by step.

How to ask good questions

Two dependencies in your POM are not publicly available, others like io.github.cdimascio:dotenv-java are missing completely, or you are relying on them to be transitive dependencies of the non-public ones, which is a Maven anti-pattern. I fixed that locally, created missing classes like the SLA annotation and EnvironmentConsumer, added a .env file containing a Timeout variable and also a TestNG test. Now I can compile and run the project. All of this would have been your job. Because you are a newbie and I needed a puzzle with my morning tea, I did it for you this time. This was your free shot. Next time, please do that by yourself. Thank you. 🙂

BTW, you also forgot to post your NullPointerException including stack trace.

Surefire falsely logging [ERROR] messages

As for Maven Surefire logging the AspectJ weaver info messages as [ERROR], you can ignore that. Probably Surefire thinks they are errors, because it does not expect any log output before the test has started running. I had discussions with the Surefire maintainers about this issue before, they do not really understand Java agents, but that is a topic for another day.

About getSLAAnnotation(Pointcut)

What I can say is that in simple cases, i.e. the intercepted method is directly annotated with something like @SLA(tiempoEsperado = 2), the method does not throw any errors. Even if the annotated method is from a super class, it works as expected. The method as such is unnecessary, as I am going explain at the end of this long answer, because AspectJ has a much more elegant way of fetching the annotation from an intercepted method or class. But let us keep that for later.

Timeout logic bug

When testing your aspect, I see that java.lang.Exception: Step timeout is always thrown, which is a bug. You have to change the faulty logic

    if (resultSla != 1 && tiempoTotal.compareTo(timeout) != 0) {
      throw new Exception("SLA Exception: Se excedió del tiempo esperado, el step duró: " + resultadoFormateado + " segundos");
    }
    else {
      throw new Exception("Step timeout");
    }

to the correct

    if (resultSla < 0)
      throw new Exception("Step timeout");
    if (timeout.compareTo(tiempoTotal) < 0)
      throw new Exception("SLA Exception: Se excedió del tiempo esperado, el step duró: " + resultadoFormateado + " segundos");

This is totally unrelated to AOP and simply a Java bug.

Unnecessary use of Duration and ZonedDateTime

Moreover, I do not understand why you work with Duration and ZonedDateTime in this case. This is slow and unnecessary, because you are not working with times from different time zones. It is also ugly that you are first converting durations to strings, only to parse them back into zoned date-times again later. Why are you making a simple thing so complicated?

You also should read the settings file only once, not every time the aspect advice is triggered, and make the settings static.

How about this simplification (please translate my English error messages to Spanish by yourself)?

  private static Dotenv settings = EnvironmentConsumer.getInstance("settings");
  private static long timeout = Long.parseLong(settings.get("Timeout"));

  private long dtFechaInicial;
  private SLA sla;

  @Before("execution(* *(..)) && @annotation(aspectPackage.SLA)")
  public void beforeTiempos(JoinPoint jp) {
    sla = getSLAAnnotation(jp);
    dtFechaInicial = currentTimeMillis();
  }

  @After("execution(* *(..)) && @annotation(aspectPackage.SLA)")
  public void afterLogger(JoinPoint jp) throws Exception {
    long tiempoTotal = currentTimeMillis() - dtFechaInicial;
    if (tiempoTotal > sla.tiempoEsperado() * 1000)
      throw new Exception(String.format(
        "Step timeout, method SLA of %d s exceeded, actual was %.2f s", 
        sla.tiempoEsperado(), tiempoTotal / 1000.0
      ));
    if (tiempoTotal > timeout * 1000)
      throw new Exception(String.format(
        "Step timeout, global SLA of %d s exceeded, actual was %.2f s",
        timeout, tiempoTotal / 1000.0
      ));
  }

Thread-unsafe use of instance fields

But even now there is one more problem. Please note that transferring state between before and after advice via instance fields is not thread-safe. Imagine that the aspect is called by multiple threads in parallel, which would be perfectly normal in business applications. You either need to use ThreadLocal fields or simply replace the before/after advice pair by one around advice:

  private static Dotenv settings = EnvironmentConsumer.getInstance("settings");
  private static long timeout = Long.parseLong(settings.get("Timeout"));

  @Around("execution(* *(..)) && @annotation(aspectPackage.SLA)")
  public Object aroundTiempos(ProceedingJoinPoint jp) throws Throwable {
    SLA sla = getSLAAnnotation(jp);
    long dtFechaInicial = currentTimeMillis();
    Object result = jp.proceed();
    long tiempoTotal = currentTimeMillis() - dtFechaInicial;
    if (tiempoTotal > sla.tiempoEsperado() * 1000)
      throw new Exception(String.format(
        "Step timeout, method SLA of %d s exceeded, actual was %.2f s",
        sla.tiempoEsperado(), tiempoTotal / 1000.0
      ));
    if (tiempoTotal > timeout * 1000)
      throw new Exception(String.format(
        "Step timeout, global SLA of %d s exceeded, actual was %.2f s",
        timeout, tiempoTotal / 1000.0
      ));
    return result;
  }

Timeout exceptions hiding application exceptions

Please note that now timeouts are only reported if the target method as such did not throw any exceptions. I think that in this case the regular error should take precedence over the timeouts. In your original solution, even if a target method threw an exception, you would throw a timeout exception instead in your @After advice, hiding the original exception. That makes application debugging difficult or even impossible. So I changed it, allowing the original exception to pass through.

How to properly fetch the @SLA annotation

You can get rid of the getSLAAnnotation(JoinPoint) method. Simply bind the annotation to the advice method, using the proper aspect syntax, adding an SLA method parameter and using its name inside the @annotation pointcut instead of the fully qualified class name. Now your complete aspect after all optimisations looks like this:

package aspectPackage;

import env.EnvironmentConsumer;
import io.github.cdimascio.dotenv.Dotenv;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;

import static java.lang.System.currentTimeMillis;

@Aspect
public class SLAAspect {
  private static Dotenv settings = EnvironmentConsumer.getInstance("settings");
  private static long timeout = Long.parseLong(settings.get("Timeout"));

  @Around("execution(* *(..)) && @annotation(sla)")
  public Object aroundTiempos(ProceedingJoinPoint jp, SLA sla) throws Throwable {
    long dtFechaInicial = currentTimeMillis();
    Object result = jp.proceed();
    long tiempoTotal = currentTimeMillis() - dtFechaInicial;
    if (tiempoTotal > sla.tiempoEsperado() * 1000)
      throw new Exception(String.format(
        "Step timeout, method SLA of %d s exceeded, actual was %.2f s",
        sla.tiempoEsperado(), tiempoTotal / 1000.0
      ));
    if (tiempoTotal > timeout * 1000)
      throw new Exception(String.format(
        "Step timeout, global SLA of %d s exceeded, actual was %.2f s",
        timeout, tiempoTotal / 1000.0
      ));
    return result;
  }
}

This is much shorter, more readable and maintainable than your original version. Along the way, we also got rid of several bugs.

GitHub example project

Everything I explained here is in my example project on GitHub. I also added a TestNG test verifying the aspect behaviour.

Answered By - kriegaex
Answer Checked By - Marie Seifert (JavaFixing Admin)