A Different Aspect On Things

Aspect Orientated Programming has been around for a long time, it’s not a new invention. However, as with an ever changing world, new requirements and inventions come in, and sometimes we look to the old, to give us inspiration for the new.

I’m not about to tell you all about the different ways you can surround your code with aspects, there are many posts out there that do that.
I want to tell you about a few ways I think that they are useful, to developers and to our customers alike.

The first is logging. How many times do you write a
LOG.debug() statement at the beginning or end of a method?
Maybe, you’d like to log requests as they come in?

Dependencies

For my example, I’ve written a simple Spring Boot Web API, and these are the dependencies I’ve used.

<dependencies>
    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-aop</artifactId>
    </dependency>
    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-web</artifactId>
    </dependency>
    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-data-jpa</artifactId>
    </dependency>
    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-test</artifactId>
        <scope>test</scope>
    </dependency>
    <dependency>
        <groupId>com.h2database</groupId>
        <artifactId>h2</artifactId>
        <version>${h2.version}</version>
    </dependency>
</dependencies>

The Logging Aspect

I want to log information about every request. How long they took, what the arguments were, and which method ran.
The execution Pointcut below picks up every public method, and the @Within Pointcut, picks up every RestController.
By combining them in the @Around I can execute the method around every method that matches. The ProceedingJoinPoint
contains all the information required about the method that will be called, and enough to actually invoke it when you are ready.
By making it a Spring @Component it is wired into the Spring ecosystem for you.

@Aspect
@Component
public class RequestLoggingAspect {

    private static final String MSG_FORMAT = "Method %s took %dms with args %s";

    private final RequestLogger requestLogger;

    public RequestLoggingAspect(final RequestLogger requestLogger) {
        this.requestLogger = requestLogger;
    }

    @Pointcut("execution(public * * (..))")
    public void getPublicMethods() {
    }

    @Pointcut("@within(org.springframework.web.bind.annotation.RestController)")
    public void getRestControllers() {
    }

    @Around("getPublicMethods() && getRestControllers()")
    public Object restControllerPublicMethods(final ProceedingJoinPoint pjp) throws Throwable {
        var sw = new StopWatch();
        var methodName = pjp.getSignature().toLongString();
        var args = Arrays.stream(pjp.getArgs())
                .map(String::valueOf)
                .collect(Collectors.joining(","));
        sw.start();
        try {
            return pjp.proceed();
        } finally {
            sw.stop();
            var msg = String.format(MSG_FORMAT, methodName, sw.getTotalTimeMillis(), args);
            requestLogger.log(msg);
        }
    }
}

The Storing Aspect

The above example logs according to your logging frameworks configuration.
It may be that you need to do something more complicated. This works in exactly the same way, but lets have a look
at an aspect that stores requests to a database.

@Aspect
@Component
public class RequestStoringAspect {

    private final RequestLogService requestLogService;
    private final MethodParser methodParser;
    private final ArgumentMatcher argumentMatcher;

    public RequestStoringAspect(final RequestLogService requestLogService,
                                final MethodParser methodParser,
                                final ArgumentMatcher argumentMatcher) {
        this.requestLogService = requestLogService;
        this.methodParser = methodParser;
        this.argumentMatcher = argumentMatcher;
    }

    @Pointcut("execution(public * * (..))")
    public void getPublicMethods() {
    }

    @Pointcut("@within(org.springframework.web.bind.annotation.RestController)")
    public void getRestControllers() {
    }

    @Around("getPublicMethods() && getRestControllers()")
    public Object restControllerPublicMethods(final ProceedingJoinPoint pjp) throws Throwable {
        var sw = new StopWatch();
        var methodSignature = pjp.getSignature().toLongString();
        var params = methodParser.parse(methodSignature);
        var args = Arrays.stream(pjp.getArgs())
                .map(String::valueOf)
                .filter(str -> !StringUtils.isNullOrEmpty(str))
                .collect(Collectors.toList());
        sw.start();
        try {
            return pjp.proceed();
        } finally {
            sw.stop();
            var arguments =  argumentMatcher.match(params, args);
            var requestLog = new RequestLogDao();
            requestLog.setArguments(arguments);
            requestLog.setExecutionMillis(sw.getTotalTimeMillis());
            requestLog.setMethodName(methodSignature);
            requestLogService.saveRequestLog(requestLog);
        }
    }
}

Here I’ve started to store some more information about the methods called, and the arguments that were captured.

This can be really useful to start to build up monitoring information. You could also start to capture audits of who has accessed different endpoints, what exceptions were thrown. This can start to build up an historic picture of your application, its performance, and what your users are really doing. It can highlight bottlenecks in the application, and can help you prioritise where you focus your efforts in your application.

Code is available here (You’ll need Java 10 or above).