Weaving aspects at compile-time with AspectJ

This is a follow-up post for Logging methods with AspectJ in a Spring application.

AspectJ manipulates Java bytecode at compile-time or load-time. The process is called weaving. Depending on when it is performed, it is called compile-time or load-time weaving. Using the same example discussed in Logging methods with AspectJ in a Spring application that uses Spring AOP, we’ll discuss how to log methods using Java and AspectJ (without any framework).

Setup

The code written for this post uses:

Java 16
AspectJ 1.9.7
JUnit 5.8.1
Maven 3.8.2

Create a Maven project using the following pom.xml.

xml
pom.xml

 1<?xml version="1.0" encoding="UTF-8"?>
 2<project xmlns="http://maven.apache.org/POM/4.0.0"
 3  xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
 4  xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
 5  <modelVersion>4.0.0</modelVersion>
 6
 7  <groupId>dev.mflash.guides.spring</groupId>
 8  <artifactId>aop-compile-time</artifactId>
 9  <version>0.0.2</version>
10
11  <properties>
12    <encoding>UTF-8</encoding>
13    <project.build.sourceEncoding>${encoding}</project.build.sourceEncoding>
14    <project.reporting.outputEncoding>${encoding}</project.reporting.outputEncoding>
15    <java.version>16</java.version>
16    <maven.compiler.source>${java.version}</maven.compiler.source>
17    <maven.compiler.target>${java.version}</maven.compiler.target>
18    <aspectj.version>1.9.7</aspectj.version>
19    <junit.version>5.8.1</junit.version>
20  </properties>
21
22  <dependencies>
23    <dependency>
24      <groupId>org.aspectj</groupId>
25      <artifactId>aspectjweaver</artifactId>
26      <version>${aspectj.version}</version>
27    </dependency>
28    <dependency>
29      <groupId>org.aspectj</groupId>
30      <artifactId>aspectjrt</artifactId>
31      <version>${aspectj.version}</version>
32      <scope>provided</scope>
33    </dependency>
34
35    <dependency>
36      <groupId>ch.qos.logback</groupId>
37      <artifactId>logback-classic</artifactId>
38      <version>1.2.6</version>
39    </dependency>
40
41    <dependency>
42      <groupId>org.assertj</groupId>
43      <artifactId>assertj-core</artifactId>
44      <version>3.21.0</version>
45      <scope>test</scope>
46    </dependency>
47    <dependency>
48      <groupId>org.junit.jupiter</groupId>
49      <artifactId>junit-jupiter-api</artifactId>
50      <version>${junit.version}</version>
51      <scope>test</scope>
52    </dependency>
53    <dependency>
54      <groupId>org.junit.jupiter</groupId>
55      <artifactId>junit-jupiter-engine</artifactId>
56      <version>${junit.version}</version>
57      <scope>test</scope>
58    </dependency>
59    <dependency>
60      <groupId>org.junit.jupiter</groupId>
61      <artifactId>junit-jupiter-params</artifactId>
62      <version>${junit.version}</version>
63      <scope>test</scope>
64    </dependency>
65  </dependencies>
66
67  <build>
68    <plugins>
69      <plugin>
70        <artifactId>maven-surefire-plugin</artifactId>
71        <version>3.0.0-M5</version>
72      </plugin>
73    </plugins>
74  </build>
75
76</project>

Define an annotation to log a method

Let’s start by defining an annotation @LogEntryExit. This annotation will control the behavior of logging done on a method.

java

 1// src/main/java/dev/mflash/guides/java/aop/logging/annotation/LogEntryExit.java
 2
 3import java.lang.annotation.ElementType;
 4import java.lang.annotation.Retention;
 5import java.lang.annotation.RetentionPolicy;
 6import java.lang.annotation.Target;
 7import java.time.temporal.ChronoUnit;
 8
 9@Retention(RetentionPolicy.RUNTIME)
10@Target(ElementType.METHOD)
11public @interface LogEntryExit {
12
13  LogLevel value() default LogLevel.INFO;
14
15  ChronoUnit unit() default ChronoUnit.SECONDS;
16
17  boolean showArgs() default false;
18
19  boolean showResult() default false;
20
21  boolean showExecutionTime() default true;
22}

This annotation can accept the following options.

a value to declare the logging level; by default, it is INFO.
a showExecutionTime flag to enable logging the execution time of the method; by default, it is true.
a unit to declare the unit of the duration of execution; by default, it is seconds.
a showArgs flag to enable displaying the arguments received by the method; by default, it is false.
a showResult flag to enable displaying the result returned by the method; by default, it is false.

LogLevel is an enum that specifies the log level.

java

1// src/main/java/dev/mflash/guides/java/aop/logging/annotation/LogEntryExit.java
2
3public enum LogLevel {
4  DEBUG, INFO, TRACE, WARN, ERROR, FATAL
5}

Define the aspect with advice to log the methods

When you annotate a method with the @LogEntryExit annotation, its entry and exit will be logged based on the options passed to it. To parse these options and set some sensible defaults on the logging behavior, let’s create an aspect LogEntryExitAspect.

java

 1// src/main/java/dev/mflash/guides/java/aop/logging/aspect/LogEntryExitAspect.java
 2
 3import dev.mflash.guides.java.aop.logging.annotation.LogEntryExit;
 4import dev.mflash.guides.java.aop.logging.annotation.LogLevel;
 5import org.aspectj.lang.ProceedingJoinPoint;
 6import org.aspectj.lang.annotation.Around;
 7import org.aspectj.lang.annotation.Aspect;
 8import org.aspectj.lang.reflect.CodeSignature;
 9import org.aspectj.lang.reflect.MethodSignature;
10import org.slf4j.Logger;
11import org.slf4j.LoggerFactory;
12
13import java.lang.reflect.Method;
14import java.time.Instant;
15import java.time.temporal.ChronoUnit;
16import java.util.HashMap;
17import java.util.Map;
18import java.util.Objects;
19import java.util.StringJoiner;
20
21@Aspect
22public final class LogEntryExitAspect {
23
24  @Around("execution(* *(..)) && @annotation(dev.mflash.guides.java.aop.logging.annotation.LogEntryExit)")
25  public Object log(ProceedingJoinPoint point) throws Throwable {
26    var codeSignature = (CodeSignature) point.getSignature();
27    var methodSignature = (MethodSignature) point.getSignature();
28    Method method = methodSignature.getMethod();
29
30    Logger logger = LoggerFactory.getLogger(method.getDeclaringClass());
31    var annotation = method.getAnnotation(LogEntryExit.class);
32    LogLevel level = annotation.value();
33    ChronoUnit unit = annotation.unit();
34    boolean showArgs = annotation.showArgs();
35    boolean showResult = annotation.showResult();
36    boolean showExecutionTime = annotation.showExecutionTime();
37    String methodName = method.getName();
38    Object[] methodArgs = point.getArgs();
39    String[] methodParams = codeSignature.getParameterNames();
40
41    log(logger, level, entry(methodName, showArgs, methodParams, methodArgs));
42
43    var start = Instant.now();
44    var response = point.proceed();
45    var end = Instant.now();
46    var duration = String.format("%s %s", unit.between(start, end), unit.name().toLowerCase());
47
48    log(logger, level, exit(methodName, duration, response, showResult, showExecutionTime));
49
50    return response;
51  }
52
53  // implementations of log, entry, exit, methods, etc.
54}

Note the pointcut expressions

execution(* *(..)) which selects all the method executions in our project
@annotation(dev.mflash.guides.java.aop.logging.annotation.LogEntryExit) which selects the methods that are annotated by the @LogEntryExit annotation

We need both expressions satisfied. By default, AspectJ applies the advices on a method call and method execution in case of an @Around aspect. The expression execution(* *(..)) ensures that methods are logged only when they are executed.

You’ll also note that the logging takes place in the log method. Such places where crosscutting actions happen are called join points in Aspect Oriented Programming (AOP). In AspectJ, a ProceedingJoinPoint allows us to inspect an execution, perform some action and proceed forward.

Here, we use the ProceedingJoinPoint to extract

extract parameter names of the method (from the CodeSignature), and
extract the details of the class, method arguments, and options passed to the @LogEntryExit annotation by this method (from the MethodSignature)

With all this information available, we calculate the execution time and prepare log messages as follows.

java

 1// src/main/java/dev/mflash/guides/java/aop/logging/aspect/LogEntryExitAspect.java
 2
 3import dev.mflash.guides.java.aop.logging.annotation.LogEntryExit;
 4import dev.mflash.guides.java.aop.logging.annotation.LogLevel;
 5import org.aspectj.lang.ProceedingJoinPoint;
 6import org.aspectj.lang.annotation.Around;
 7import org.aspectj.lang.annotation.Aspect;
 8import org.aspectj.lang.reflect.CodeSignature;
 9import org.aspectj.lang.reflect.MethodSignature;
10import org.slf4j.Logger;
11import org.slf4j.LoggerFactory;
12
13import java.lang.reflect.Method;
14import java.time.Instant;
15import java.time.temporal.ChronoUnit;
16import java.util.HashMap;
17import java.util.Map;
18import java.util.Objects;
19import java.util.StringJoiner;
20
21@Aspect
22public final class LogEntryExitAspect {
23
24  @Around("execution(* *(..)) && @annotation(dev.mflash.guides.java.aop.logging.annotation.LogEntryExit)")
25  public Object log(ProceedingJoinPoint point) throws Throwable {
26    var codeSignature = (CodeSignature) point.getSignature();
27    var methodSignature = (MethodSignature) point.getSignature();
28    Method method = methodSignature.getMethod();
29
30    Logger logger = LoggerFactory.getLogger(method.getDeclaringClass());
31    var annotation = method.getAnnotation(LogEntryExit.class);
32    LogLevel level = annotation.value();
33    ChronoUnit unit = annotation.unit();
34    boolean showArgs = annotation.showArgs();
35    boolean showResult = annotation.showResult();
36    boolean showExecutionTime = annotation.showExecutionTime();
37    String methodName = method.getName();
38    Object[] methodArgs = point.getArgs();
39    String[] methodParams = codeSignature.getParameterNames();
40
41    log(logger, level, entry(methodName, showArgs, methodParams, methodArgs));
42
43    var start = Instant.now();
44    var response = point.proceed();
45    var end = Instant.now();
46    var duration = String.format("%s %s", unit.between(start, end), unit.name().toLowerCase());
47
48    log(logger, level, exit(methodName, duration, response, showResult, showExecutionTime));
49
50    return response;
51  }
52
53  static String entry(String methodName, boolean showArgs, String[] params, Object[] args) {
54    StringJoiner message = new StringJoiner(" ")
55        .add("Started").add(methodName).add("method");
56
57    if (showArgs && Objects.nonNull(params) && Objects.nonNull(args) && params.length == args.length) {
58
59      Map<String, Object> values = new HashMap<>(params.length);
60
61      for (int i = 0; i < params.length; i++) {
62        values.put(params[i], args[i]);
63      }
64
65      message.add("with args:")
66          .add(values.toString());
67    }
68
69    return message.toString();
70  }
71
72  static String exit(String methodName, String duration, Object result, boolean showResult, boolean showExecutionTime) {
73    StringJoiner message = new StringJoiner(" ")
74        .add("Finished").add(methodName).add("method");
75
76    if (showExecutionTime) {
77      message.add("in").add(duration);
78    }
79
80    if (showResult) {
81      message.add("with return:").add(result.toString());
82    }
83
84    return message.toString();
85  }
86
87  static void log(Logger logger, LogLevel level, String message) {
88    switch (level) {
89      case DEBUG -> logger.debug(message);
90      case TRACE -> logger.trace(message);
91      case WARN -> logger.warn(message);
92      case ERROR, FATAL -> logger.error(message);
93      default -> logger.info(message);
94    }
95  }
96}

Here

the entry method prepares a log message containing parameter names and arguments of the method, and
the exit method prepares a log message containing execution time and the returned value

Configuring the AspectJ Compiler

To modify the bytecode of methods annotated by the @LogEntryExit annotation, you’ll need to configure AspectJ Compiler (ajc in short). An easy way to do this is by using Mojo’s Aspect Maven Plugin. Open your pom.xml and modify it as follows.

xml

 1<?xml version="1.0" encoding="UTF-8"?>
 2<project xmlns="http://maven.apache.org/POM/4.0.0"
 3  xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
 4  xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
 5  <modelVersion>4.0.0</modelVersion>
 6
 7  <!-- rest of the POM -->
 8
 9  <build>
10    <plugins>
11      <plugin>
12        <artifactId>maven-surefire-plugin</artifactId>
13        <version>3.0.0-M5</version>
14      </plugin>
15      <plugin>
16        <groupId>org.codehaus.mojo</groupId>
17        <artifactId>aspectj-maven-plugin</artifactId>
18        <version>1.14.0</version>
19        <configuration>
20          <complianceLevel>16</complianceLevel>
21          <showWeaveInfo>true</showWeaveInfo>
22          <encoding>${encoding}</encoding>
23          <Xlint>ignore</Xlint>
24        </configuration>
25        <executions>
26          <execution>
27            <goals>
28              <goal>compile</goal>
29              <goal>test-compile</goal>
30            </goals>
31          </execution>
32        </executions>
33      </plugin>
34    </plugins>
35  </build>
36
37</project>

Note that the ajc is configured to weave the classes during compile and test-compile goals of Maven’s lifecycle. We’re also passing the following configuration through the plugin.

Xlint to log an error or warning message if something goes wrong with the Aspect code. You can also set it to ignore all the issues.
showWeaveInfo displays useful details during weaving
complianceLevel sets the source code and bytecode target version for Java

Compile-time weaving in action

To check if the above implementation works, create a class, say GreetingHandler with some sample methods.

java

 1// src/main/java/dev/mflash/guides/java/aop/logging/GreetingHandler.java
 2
 3import dev.mflash.guides.java.aop.logging.annotation.LogEntryExit;
 4
 5import java.time.temporal.ChronoUnit;
 6
 7public class GreetingHandler {
 8
 9  @LogEntryExit(showArgs = true, showResult = true, unit = ChronoUnit.MILLIS)
10  public String greet(String name) {
11    return "Hello, " + resolveName(name) + "!";
12  }
13
14  @LogEntryExit(showArgs = true, showResult = true, unit = ChronoUnit.MILLIS)
15  private String resolveName(String name) {
16    return !name.isBlank() ? name : "world";
17  }
18
19  public String resolveNothing(String randomString) {
20    return "All good, nothing to resolve!";
21  }
22}

Here, the public method greet and private method resolveName are annotated with the @LogEntryExit annotation, and hence we expect them to be logged.

Create a Launcher class to call these methods as follows.

java

 1// src/main/java/dev/mflash/guides/java/aop/logging/Launcher.java
 2
 3import org.slf4j.Logger;
 4import org.slf4j.LoggerFactory;
 5
 6public class Launcher {
 7
 8  private static final Logger logger = LoggerFactory.getLogger(Launcher.class);
 9
10  private static final GreetingHandler handler = new GreetingHandler();
11
12  public static void main(String... args) {
13    logger.info("{}", handler.greet("Veronica"));
14  }
15}

Running the Launcher outputs the following logs.

log

116:54:35.272 [main] INFO dev.mflash.guides.java.aop.logging.GreetingHandler - Started greet method with args: {name=Veronica}
216:54:35.272 [main] INFO dev.mflash.guides.java.aop.logging.GreetingHandler - Started resolveName method with args: {name=Veronica}
316:54:35.272 [main] INFO dev.mflash.guides.java.aop.logging.GreetingHandler - Finished resolveName method in 0 millis with return: Veronica
416:54:35.272 [main] INFO dev.mflash.guides.java.aop.logging.GreetingHandler - Finished greet method in 0 millis with return: Hello, Veronica!
516:54:35.272 [main] INFO dev.mflash.guides.java.aop.logging.Launcher - Hello, Veronica!

Feel free to play with other options of the @LogEntryExit annotation.

Testing the aspect

To test the LogEntryExitAspect, you can monitor the logs and verify if the expected messages are printed during the execution. Logback provides an API to capture logging events. We can use this API

to define a custom log appender, say AspectAppender
attach this appender to the logger of GreetingHandler class
call the methods of the GreetingHandler class, and
query the captured events to verify that entry and exit logs

Let’s define the AspectAppender as follows.

java

 1// src/test/java/dev/mflash/guides/java/aop/logging/AspectAppender.java
 2
 3import ch.qos.logback.classic.spi.ILoggingEvent;
 4import ch.qos.logback.core.AppenderBase;
 5
 6import java.util.ArrayList;
 7import java.util.List;
 8
 9public class AspectAppender extends AppenderBase<ILoggingEvent> {
10
11  public final List<ILoggingEvent> events = new ArrayList<>();
12
13  @Override
14  protected void append(ILoggingEvent event) {
15    events.add(event);
16  }
17}

Now use this appender in the JUnit test to verify success and failure scenarios for the aspect.

java

 1// src/test/java/dev/mflash/guides/java/aop/logging/aspect/LogEntryExitAspectTest.java
 2
 3import static org.assertj.core.api.Assertions.assertThat;
 4
 5import ch.qos.logback.classic.Logger;
 6import ch.qos.logback.classic.LoggerContext;
 7import dev.mflash.guides.java.aop.logging.AspectAppender;
 8import dev.mflash.guides.java.aop.logging.GreetingHandler;
 9import org.junit.jupiter.api.AfterEach;
10import org.junit.jupiter.api.BeforeEach;
11import org.junit.jupiter.api.DisplayName;
12import org.junit.jupiter.api.Test;
13import org.slf4j.LoggerFactory;
14
15class LogEntryExitAspectTest {
16
17  private GreetingHandler greetingHandler;
18  private AspectAppender aspectAppender;
19
20  @BeforeEach
21  void setUp() {
22    greetingHandler = new GreetingHandler();
23
24    aspectAppender = new AspectAppender();
25    aspectAppender.setContext(new LoggerContext());
26    aspectAppender.start();
27
28    final Logger logger = (Logger) LoggerFactory.getLogger(GreetingHandler.class);
29    logger.addAppender(aspectAppender);
30  }
31
32  @AfterEach
33  void cleanUp() {
34    aspectAppender.stop();
35  }
36
37  @Test
38  @DisplayName("Should fire advice with logs on public method")
39  void shouldFireAdviceWithLogsOnPublicMethod() {
40    greetingHandler.greet("Veronica");
41
42    assertThat(aspectAppender.events).isNotEmpty()
43        .anySatisfy(event -> assertThat(event.getMessage())
44            .isEqualTo("Started greet method with args: {name=Veronica}")
45        )
46        .anySatisfy(event -> assertThat(event.getMessage())
47            .startsWith("Finished greet method in ")
48            .endsWith("millis with return: Hello, Veronica!")
49        );
50  }
51
52  @Test
53  @DisplayName("Should fire advice with logs on private method")
54  void shouldFireAdviceWithLogsOnPrivateMethod() {
55    greetingHandler.greet("Veronica");
56
57    assertThat(aspectAppender.events).isNotEmpty()
58        .anySatisfy(event -> assertThat(event.getMessage())
59            .isEqualTo("Started resolveName method with args: {name=Veronica}")
60        )
61        .anySatisfy(event -> assertThat(event.getMessage())
62            .startsWith("Finished resolveName method in ")
63            .endsWith("millis with return: Veronica")
64        );
65  }
66
67  @Test
68  @DisplayName("Should not fire advice without annotation")
69  void shouldNotFireAdviceWithoutAnnotation() {
70    greetingHandler.resolveNothing("Veronica");
71
72    assertThat(aspectAppender.events).isEmpty();
73  }
74}

Here, we

attach the AspectAppender to the logger of the GreetingHandler in the setup method. We stop the appender in the cleanUp method after every test.
verify if the entry and exit of the GreetingHandler.greet and GreetingHandler.resolveName are logged
verify that the entry and exit of the GreetingHandler.resolveNothing method are not logged since it is not annotated with the @LogEntryExit annotation.

Conclusion

Compile-time weaving is pretty fast since all the bytecode is already weaved before execution.
It requires access to the source code. If source code is not available, you’ll have to use build-time or load-time weaving. Spring AOP, for example, uses load-time weaving using proxies.
You can weave public or private methods of a Java class.
It is relatively simpler compared to build-time or load-time weaving which need an agent to weave the classes.
It introduces another compiler, ajc, in the compile process. Some IDEs may not provide support for this compiler out-of-box.

Source code

aop-compile-time

Creating deep copies in Java