Kotlin logging with Spring AOP

Why use AOP

AOP (Aspect-Oriented Programming) is a programming paradigm that increases the modularity of a project. It achieves that by separating (or, better, allowing the separation of) the cross-cutting concerns. A cross-cutting concern is a concern that can affect the whole application and should be centralized in one location in code as possible, such as logging, authentication, etc. With this in mind, AOP provides the right tools to get rid of the boilerplate code from your project. While the key unit of modularity in OOP is the class, in AOP it’s the aspect.

Key AOP Concepts

• Aspect: a modularization of a concern that cuts across multiple classes.
• Join point: a point during the execution of a program, it represents a method execution.
• Advice: it represents the action to be taken by an aspect at a particular join point. It behaves like an interceptor, and can execute a block of code at different stages of a method execution. There are multiple types of advices:
• Before: the advice is executed before a join point. It does not have the ability to prevent the execution flow proceeding to the join point, execept for the case when it throws an exception, but that will make the code harder to read and it will be harder to prevent it from failing.
• After returning: the advice is executed after a join point completes normally: for example, if a method returns without throwing an exception.
• After throwing: the advice is executed if a method exits by throwing an exception.
• After: the advice is executed regardless of the means by which a join point exits (it’s a combination of the two above).
• Around advice: the advice surrounds a join point such as a method invocation. This is the most powerful kind of advice, and a combination of all of the advices described above, meaning that it can perform custom behavior before and after the method invocation. It is also responsible for choosing whether to proceed to the join point or to shortcut the advised method execution by returning its own return value or throwing an exception.
• Pointcut: a predicate that matches join points. Advice is associated with a pointcut expression and runs at any join point matched by the pointcut (for example, the execution of a method with a certain name, or the execution of a method that is annotated with a given annotation).
• Target object: object being advised by one or more aspects. Also referred to as the advised object.

Example

The concepts described above might not make a lot of sense right now, but let’s put them into practice and see how everything ties together.

In this example, we have a project started with Gradle Kotlin DSL and the following spring dependencies:

implementation("org.springframework.boot:spring-boot-starter")
implementation("org.springframework.boot:spring-boot-starter-web")
implementation("org.springframework.boot:spring-boot-starter-aop")

In code, we have an advice that is being executed any time a method that is annotated with @LogExecution is being called. First we will go over it, then we will explore what alternatives we have.

Overview

In the example, we have defined an annotation LogExecution that is targeted on functions.

@Target(AnnotationTarget.FUNCTION)
@Retention(AnnotationRetention.RUNTIME)
annotation class LogExecution

Then, we have defined an aspect LogAspect, which is just a class annotated with @Aspect and @Component/@Configuration.

@Aspect
@Component
class LogAspect {
    ...
}

In this aspect we can define our advices. The advice defined in our example is annotated with @Around so that we can log both the start and the end of the method execution, including the execution time.

@Around("@annotation(com.example.annotation.LogExecution)")
fun logExecutionTime(joinPoint: ProceedingJoinPoint): Any {
    ...
    joinPoint.proceed()
    ...
}

And we are all set. All we need to do now is to set our annotation on the functions that we want to log.

@LogExecution
fun test(): String

Result

The output of this can be seen when we will call the GET /hello API:

2019-09-15 20:22:42.821  INFO 2912 --- [nio-8080-exec-1] com.example.advice.LogAspect             : start -> Executing HelloWorldController.test(), parameters: []
2019-09-15 20:22:42.844  INFO 2912 --- [nio-8080-exec-1] com.example.advice.LogAspect             : start -> Executing HelloWorldService.sayHello(), parameters: []
2019-09-15 20:22:42.861  INFO 2912 --- [nio-8080-exec-1] com.example.advice.LogAspect             : end -> Finished executing: HelloWorldService.sayHello(), returned: 'Hello World!', duration: 17 ms
2019-09-15 20:22:42.861  INFO 2912 --- [nio-8080-exec-1] com.example.advice.LogAspect             : end -> Finished executing: HelloWorldController.test(), returned: 'Hello World!', duration: 54 ms

As you see, 2 method calls were logged: 1 from the test() function from our controller and 1 from the sayHello() function from our service.

Note

If we have defined 2 methods in the same Spring Component, both annotated with @LogExecution and one calling the other, only the first method call will be logged. The reason is that calls within the same class does not go though the Spring proxy. The call to the first method is proxied and will be handled by AOP but the second method might as well be private.

Alternatives

An alternative to this is to get rid of the annotation that we created and define the pointcut of our advice to match exactly the method we want logged, or to match a whole package.

Examples:

@Pointcut("execution(public String com.example.test.HelloWorldController.test())")
@Pointcut("execution(* com.example.test.HelloWorldController.*(..))")

How else can AOP be used

AOP can also be used to mock methods. For example, if you want to do performance testing on your application but you have an external dependency, you can easily mock the method calls using AOP: you can define your advice annotated with @Around and return a mock instead of the actual result.

References

• Aspect Oriented Programming with Spring