A Simple Example of Using Spring Aspect Oriented Programming to Log the Beginning and End of All Methods in All Classes in a Package

I have often seen, in development work, certain types of code fragments that get repeated many times throughout the code, which would seem a prime use case for Aspect Oriented Programming (AOP). I thought I would try creating an aspect to do debug logging in my Biking Weather Suitability Forecast application as follows:

1. Do the following debug logging items for all methods in all classes in the biz.noip.johnwatne.bikingweather.service package.
2. Log the start of a method's execution, including the name of the method and listing the parameters passed to it.
3. For methods that return an Object or value, log the item returned.
4. For void methods, indicate the end of the method's execution.
5. Allow toggling the enabling of the aspect's code based on the value of a property in the application's properties file. This allows temporarily enabling the logging while testing new development, then disabling it, or, alternatively, having environment-specific properties files that would have differing values depending on whether or not the logging was desired for that environment.

The application had already been written using Spring Boot. After doing a bit of research on Spring AOP, I decided to use Spring AspectJ annotations to make an aspect out of a POJO (Plain Old Java Object).

The first step was to enable Spring Boot AOP by adding the following dependency to the dependencies section of the application's pom.xml file:

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-aop</artifactId>
        </dependency>

Similar dependencies could be added for Spring without using Spring Boot, but I did not explore those options for my application. After creating a new package to contain aspects for the application, I added the following single class to it:

package biz.noip.johnwatne.bikingweather.aspects;

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

/**
 * Logging aspect.
 *
 * @author John Watne
 *
 */
@Aspect
@Component
public class LoggingAspect {
    private static final Logger LOGGER =
            LoggerFactory.getLogger(LoggingAspect.class);

    @Before("execution(* biz.noip.johnwatne.bikingweather.service..*(..))")
    public void logMethodStart(final JoinPoint joinPoint) {
        LOGGER.debug("*** Starting " + joinPoint.getSignature().getName());

        for (Object arg : joinPoint.getArgs()) {
            LOGGER.debug("****** " + arg);
        }
    }
}

1. The @Aspect annotation indicates that this is an aspect.
2. The @Component annotation makes this a Spring Bean.
3. The @Before annotation indicates that this is code to be inserted at the start of every method matching the criteria specified within its "execution" parameter. The breakdown of the argument passed to execution is as follows:
   1. The "*" before the package specification indicates that it applies to methods of all return types.
   2. "biz.noip.johnwatne.bikingweather.service..*(..)" indicates that all methods within the specified package, with any combination of parameters passed to them, are to have the annotated code executed at the start of the method.
4. The JoinPoint parameter passed to the "advice" method indicates where the "advice" method's code gets joined to the main code of the program. joinPoint.getSignature.getName() returns the name of the method receiving the "advice", and joinPoint.getArgs() gives a List of all the parameters passed to that method.

Having created this class with the @Component annotation, I added the class to the list of basePackageClasses in the @ComponentScan annotation on my main application class, as follows.

@SpringBootApplication(exclude = {DataSourceAutoConfiguration.class})
@ComponentScan(basePackageClasses = {ForecastController.class,
        DailyAndHourlySuitabilityForDay.class,
        DailyReportCollectionService.class, LoggingAspect.class})
public class BikingweatherApplication extends SpringBootServletInitializer {

After confirming that the @Before-annotated advice worked, I added the following two methods to the LoggingAspect class. The first uses the @AfterReturning annotation in order to get the value returned by the method, and the second should indicate the completion of executing a void method.

    @AfterReturning(
            value = "execution(* biz.noip.johnwatne.bikingweather.service..*(..))",
            returning = "result")
    public void logReturnValue(final JoinPoint joinPoint, final Object result) {
        LOGGER.debug("*** " + joinPoint.getSignature().getName() + " returns "
                + result);
    }

    @After("execution(void biz.noip.johnwatne.bikingweather.service..*(..))")
    public void logReturnFromVoidMethod(final JoinPoint joinPoint) {
        LOGGER.debug(
                "*** end void method " + joinPoint.getSignature().getName());
    }

The following log excerpt gives an example of the code generated by these "advice" methods.

2020-11-23 02:06:45,522 DEBUG biz.noip.johnwatne.bikingweather.aspects.LoggingAspect [http-nio-1986-exec-7] *** Starting getForecastRequest
2020-11-23 02:06:45,552 DEBUG biz.noip.johnwatne.bikingweather.aspects.LoggingAspect [http-nio-1986-exec-7] *** getForecastRequest returns ForecastRequest{url=https://api.darksky.net/forecast/0f57d37e9e219b7569810eb003a03073/44.887321,-93.312086?lang=en&units=us&exclude=minutely}
2020-11-23 02:06:46,729 INFO biz.noip.johnwatne.bikingweather.service.DailyReportCollectionService [http-nio-1986-exec-7] *** Obtaining new NWS forecast ***
2020-11-23 02:06:46,730 DEBUG biz.noip.johnwatne.bikingweather.aspects.LoggingAspect [http-nio-1986-exec-7] *** Starting getHourlyForecast
2020-11-23 02:06:48,506 DEBUG biz.noip.johnwatne.bikingweather.aspects.LoggingAspect [http-nio-1986-exec-7] *** getHourlyForecast returns HourlyForecast [getType()=Feature, getGeometry()=biz.noip.johnwatne.bikingweather.model.nws.Geometry@2e6896d, getProperties()=
Properties [getUpdated()=2020-11-23T05:09:17+00:00, getUnits()=us, getForecastGenerator()=HourlyForecastGenerator, getGeneratedAt()=2020-11-23T08:06:48+00:00, getUpdateTime()=2020-11-23T05:09:17+00:00, getValidTimes()=2020-11-22T23:00:00+00:00/P7DT2H, getPeriods()=[
Period [getNumber()=1, getStartTime()=2020-11-23T02:00:00-06:00, getEndTime()=2020-11-23T03:00:00-06:00, isDaytime()=false, getTemperature()=27, getTemperatureUnit()=F, getWindSpeed()=5 mph, getWindDirection()=NW, getIcon()=https://api.weather.gov/icons/land/night/sct?size=small, getShortForecast()=Partly Cloudy], 
.
.
.

Finally, I added the @ConditionalOnProperty(...) annotation to the LoggingAspect class such that the class would only have its code injected into methods if the expanded.logging property was defined with a value of true.

@Aspect
@Component
@ConditionalOnProperty(prefix = "expanded", name = "logging",
        havingValue = "true")
public class LoggingAspect {
.
.
.

This code is enabled by adding the following line to the application's application.properties file.

expanded.logging=true

Note that the @ConditionalOnProperty is a configuration annotation for Spring Boot. It should be possible to do something comparable in Spring, without Spring Boot, using the @Conditional annotation added in Spring 4. The class implementing the Condition interface would be responsible for checking the value of the expanded.logging property, in this case.

This was an interesting first experiment with Aspect Oriented Programming. I hope that this example, and the links above, may be of use to others interested in exploring this subject.