Logging methods with AspectJ in a Spring application

Method logging is a common pattern to collect data about a method. This could be execution time, the inputs and outputs of the method, etc. You can do this by using a logger but since this is a repetitive task, it makes sense to automate it. That’s exactly what we’ll do in this post.

Setup

The code written for this post uses:

Java 16
Spring Boot 2.5.4
AspectJ 1.9.7
Maven 3.8.2

Generate a Maven project using the following pom.xml.

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  <parent>
 8    <groupId>org.springframework.boot</groupId>
 9    <artifactId>spring-boot-starter-parent</artifactId>
10    <version>2.5.2</version>
11    <relativePath/> <!-- lookup parent from repository -->
12  </parent>
13
14  <groupId>dev.mflash.guides.spring</groupId>
15  <artifactId>aop-method-logging</artifactId>
16  <version>0.0.3</version>
17
18  <properties>
19    <java.version>16</java.version>
20  </properties>
21
22  <dependencies>
23    <dependency>
24      <groupId>org.springframework.boot</groupId>
25      <artifactId>spring-boot-starter</artifactId>
26    </dependency>
27
28    <dependency>
29      <groupId>org.aspectj</groupId>
30      <artifactId>aspectjweaver</artifactId>
31    </dependency>
32    <dependency>
33      <groupId>org.aspectj</groupId>
34      <artifactId>aspectjrt</artifactId>
35      <scope>runtime</scope>
36    </dependency>
37
38    <dependency>
39      <groupId>org.springframework.boot</groupId>
40      <artifactId>spring-boot-starter-test</artifactId>
41      <scope>test</scope>
42    </dependency>
43  </dependencies>
44
45  <build>
46    <plugins>
47      <plugin>
48        <groupId>org.springframework.boot</groupId>
49        <artifactId>spring-boot-maven-plugin</artifactId>
50      </plugin>
51    </plugins>
52  </build>
53
54</project>

Define an annotation to log a method

You can create aspects by configuring an advice in a variety of ways. You can apply an advice on all classes in specified packages. But, you may not need to log all the methods, or you may want to log some methods differently. To do this, you can define an annotation, as follows, and annotate the methods that you need to log. By passing values to the annotation, you can customize the logging behavior.

java

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

The @LogEntryExit annotation can accept

a value that declares 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 that declares the unit of the duration of execution; by default, it is seconds.
a showArgs flag to toggle whether to display the arguments received by the method; by default, it is false.
a showResult flag to toggle whether to display the result returned by the method; by default, it is false.

Define the aspect with an advice to log the methods

Apply the advice around the methods annotated with @LogEntryExit annotation, as follows.

java

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

There’s a lot to digest here. The LogEntryExitAspect class has a log method that accepts a JoinPoint.

Here, we want to apply an advice around a method that’s annotated by @LogEntryExit annotation, and proceed with the execution. That’s what a ProceedingJoinPoint provides the support for.

Furthermore, we obtain

CodeSignature to get the parameter names of the join point.
MethodSignature to find the current instance of the @LogEntryExit annotation and its associated options. Using them, we customize the logging output by calling a static log method.
MethodSignature to fetch the details of the class that contains the method. MethodSignature also provides the method’s name and the list of arguments it receives.

The following static log method logs the messages based on the log level specified in the annotation. We need to do this because Spring Boot uses SLF4J 1.7 which does not provide an API to pass the log level at runtime.

java

 1// src/main/java/dev/mflash/guides/spring/aop/logging/aspect/LogEntryExitAspect.java
 2
 3@Aspect
 4@Component
 5public class LogEntryExitAspect {
 6
 7  // rest of the code
 8
 9  static void log(Logger logger, LogLevel level, String message) {
10    switch (level) {
11      case DEBUG -> logger.debug(message);
12      case TRACE -> logger.trace(message);
13      case WARN -> logger.warn(message);
14      case ERROR, FATAL -> logger.error(message);
15      default -> logger.info(message);
16    }
17  }
18}

We’ve also defined entry and exit methods to prepare the log message based on the options received by the annotation.

java

 1// src/main/java/dev/mflash/guides/spring/aop/logging/aspect/LogEntryExitAspect.java
 2
 3@Aspect
 4@Component
 5public class LogEntryExitAspect {
 6
 7  // rest of the code
 8
 9  static String entry(String methodName, boolean showArgs, String[] params, Object[] args) {
10    StringJoiner message = new StringJoiner(" ")
11        .add("Started").add(methodName).add("method");
12
13    if (showArgs && Objects.nonNull(params) && Objects.nonNull(args) && params.length == args.length) {
14
15      Map<String, Object> values = new HashMap<>(params.length);
16
17      for (int i = 0; i < params.length; i++) {
18        values.put(params[i], args[i]);
19      }
20
21      message.add("with args:")
22          .add(values.toString());
23    }
24
25    return message.toString();
26  }
27
28  static String exit(String methodName, String duration, Object result, boolean showResult, boolean showExecutionTime) {
29    StringJoiner message = new StringJoiner(" ")
30        .add("Finished").add(methodName).add("method");
31
32    if (showExecutionTime) {
33      message.add("in").add(duration);
34    }
35
36    if (showResult) {
37      message.add("with return:").add(result.toString());
38    }
39
40    return message.toString();
41  }
42
43  // rest of the code
44}

In the entry method, we generate a map of parameters and arguments of the method, and add them to the log message if showArgs flag is set to true. Similarly, we add the duration of execution, and the result returned by the method to the log message based on the showExecutionTime and showResult flags respectively.

Together the entire implementation looks like this.

java

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

Spring AOP works in tandem with Spring IoC container by creating dynamic proxies for AOP proxies (more details here). Thus, we need to mark the aspect as a bean (using Component stereotype annotation).

Method logging in action

To demonstrate the usage, create a GreetingService with a method annotated with @LogEntryExit annotation as follows.

java

 1// src/main/java/dev/mflash/guides/spring/aop/logging/service/GreetingService.java
 2
 3import dev.mflash.guides.spring.aop.logging.annotation.LogEntryExit;
 4import org.springframework.stereotype.Service;
 5
 6import java.time.temporal.ChronoUnit;
 7
 8@Service
 9public class GreetingService {
10
11  @LogEntryExit(showArgs = true, showResult = true, unit = ChronoUnit.MILLIS)
12  public String greet(String name) {
13    return "Hello, " + resolveName(name) + "!";
14  }
15
16  public String resolveName(String name) {
17    return !name.isBlank() ? name : "world";
18  }
19}

Inject this service in the Launcher and call it through CommandLineRunner.

java

 1// src/main/java/dev/mflash/guides/spring/aop/logging/Launcher.java
 2
 3import dev.mflash.guides.spring.aop.logging.service.GreetingService;
 4import org.springframework.boot.CommandLineRunner;
 5import org.springframework.boot.SpringApplication;
 6import org.springframework.boot.autoconfigure.SpringBootApplication;
 7
 8@SpringBootApplication
 9public class Launcher implements CommandLineRunner {
10
11  private final GreetingService greetingService;
12
13  public Launcher(GreetingService greetingService) {
14    this.greetingService = greetingService;
15  }
16
17  public static void main(String... args) {
18    SpringApplication.run(Launcher.class, args);
19  }
20
21  @Override
22  public void run(String... args) throws Exception {
23    greetingService.greet("Joe");
24    greetingService.greet("Jane");
25  }
26}

Launch the application and you’d see the method logs on the console.

log

12021-07-18 17:10:31.422  INFO 9012 --- [main] d.m.g.s.a.l.service.GreetingService : Started greet method with args: {name=Joe}
22021-07-18 17:10:31.422  INFO 9012 --- [main] d.m.g.s.a.l.service.GreetingService : Finished greet method in 0 millis with return: Hello, Joe!
32021-07-18 17:10:31.422  INFO 9012 --- [main] d.m.g.s.a.l.service.GreetingService : Started greet method with args: {name=Jane}
42021-07-18 17:10:31.422  INFO 9012 --- [main] d.m.g.s.a.l.service.GreetingService : Finished greet method in 0 millis with return: Hello, Jane!

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

Testing the aspect

To test whether the log method is applying the advice on the annotated method, you can monitor the logged events and apply assertions on them. Unfortunately, SLF4J doesn’t provide an API to do this. But, you can leverage Logback’s API (the default underlying logger in Spring) to get a list of logged events. To do this, define a custom appender.

java

 1// src/test/java/dev/mflash/guides/spring/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}

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

java

 1// src/test/java/dev/mflash/guides/spring/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.spring.aop.logging.AspectAppender;
 8import dev.mflash.guides.spring.aop.logging.ServiceProxyProvider;
 9import dev.mflash.guides.spring.aop.logging.service.GreetingService;
10import org.junit.jupiter.api.AfterEach;
11import org.junit.jupiter.api.BeforeEach;
12import org.junit.jupiter.api.DisplayName;
13import org.junit.jupiter.api.Test;
14import org.slf4j.LoggerFactory;
15
16class LogEntryExitAspectTest {
17
18  private GreetingService greetingService;
19  private AspectAppender aspectAppender;
20
21  @BeforeEach
22  void setUp() {
23    greetingService = (GreetingService) ServiceProxyProvider.getServiceProxy(new GreetingService());
24
25    aspectAppender = new AspectAppender();
26    aspectAppender.setContext(new LoggerContext());
27    aspectAppender.start();
28
29    final Logger logger = (Logger) LoggerFactory.getLogger(GreetingService.class);
30    logger.addAppender(aspectAppender);
31  }
32
33  @AfterEach
34  void cleanUp() {
35    aspectAppender.stop();
36  }
37
38  @Test
39  @DisplayName("Should fire advice with logs")
40  void shouldFireAdviceWithLogs() {
41    greetingService.greet("Veronica");
42
43    assertThat(aspectAppender.events).isNotEmpty()
44        .anySatisfy(event -> assertThat(event.getMessage())
45            .isEqualTo("Started greet method with args: {name=Veronica}")
46        )
47        .anySatisfy(event -> assertThat(event.getMessage())
48            .startsWith("Finished greet method in ")
49            .endsWith("millis with return: Hello, Veronica!")
50        );
51  }
52
53  @Test
54  @DisplayName("Should not fire advice without annotation")
55  void shouldNotFireAdviceWithoutAnnotation() {
56    greetingService.resolveName("Veronica");
57
58    assertThat(aspectAppender.events).isEmpty();
59  }
60}

In this test,

the setUp method initializes the GreetingService using the ServiceProxyProvider factory class. It also initializes the AspectAppender defined earlier and attaches it to the logger of the GreetingService; whenever the methods of this service get called, a logging event gets added to the list maintained by AspectAppender.
the cleanUp method tears down the appender.
the first test verifies the positive case that the logs are written when the GreetingService.greet method is called.
the second test verifies the negative case that the logs are not written for the methods without @LogEntryExit annotation.

The ServiceProxyProvider factory class used in the setUp method

accepts a type (of a Spring Bean),
initializes the LogEntryExitAspect,
injects it in an AopProxy, and
returns an instance of the proxy of the specified type.

We need the proxied bean because that’s how Spring AOP applies the advices.

java

 1// src/test/java/dev/mflash/guides/spring/aop/logging/ServiceProxyProvider.java
 2
 3import dev.mflash.guides.spring.aop.logging.aspect.LogEntryExitAspect;
 4import org.springframework.aop.aspectj.annotation.AspectJProxyFactory;
 5import org.springframework.aop.framework.AopProxy;
 6import org.springframework.aop.framework.DefaultAopProxyFactory;
 7
 8public final class ServiceProxyProvider {
 9
10  private ServiceProxyProvider() {}
11
12  public static Object getServiceProxy(Object service) {
13    final var entryExitAspect = new LogEntryExitAspect();
14    final var proxyFactory = new AspectJProxyFactory(service);
15    proxyFactory.addAspect(entryExitAspect);
16
17    final AopProxy aopProxy = new DefaultAopProxyFactory().createAopProxy(proxyFactory);
18
19    return aopProxy.getProxy();
20  }
21}

Limitations of this approach

You cannot selectively ignore the logged arguments. If a value is sensitive (for legal or security reasons), this implementation is not flexible enough to handle such a usecase (although, it can be extended to handle them).
This approach relies on Spring AOP; it doesn’t work with classes that the Spring IoC container is not aware of.
All the limitations of Spring AOP and Aspects apply to this approach; you can’t log private methods and you can’t extend this approach for advising the fields.

Source code

aop-method-logging

API Documentation with Springfox 3