One of the most useful features provided by Spring is easy access to Aspect Oriented programming or AOP. AOP is used to separate cross-cutting concerns and provide modular codes without doing any update to the code being referred. So, we can add a Pointcut to specify when a command has to be executed. Pointcuts are executed on JoinPoints and we can specify what action has to be taken.
Terminology
Aspects: Aspects are implementations spanning across multiple classes. Logging is an example of such an implementation. We will be logging throughout the application, and we can push any common logging definition into an aspect class.
Advice: This will work in conjunction with JoinPoints. It defines a set of instructions (method) that is executed when a particular join point is reached. So consider join points as events that will trigger a particular advice to be executed.
JoinPoints: This is the point in the application where the advice will be triggered. It can be method execution, exception handling routines etc.
PointCut: Pointcut defines if advice has to be executed on JoinPoints when they are hit. SpringBoot will evaluate the condition provided in the point cut and execute the advice only when the expression matches.
ProceedingJoinPoint: This is used only with @Around advice. Proceeding join point is used to move forward in the execution.
Pointcut Designators
execution: This is the default designator. It will be matched when a method is executed.
within: This works the same way as execution. We can use within to match only some advices.
@annotation: This tag only matches classes annotated with defined annotation.
@args: This is a specific use case where the match only happens when the method argument matches the defined type.
target: This will only match when the target object is of the defined type.
@target: Quite different from the previous, this is used for matching classes where execution object has an annotation of the given type
Advice Types
@Before: Executes before join point execution
@After: Executes after join point execution
@AfterReturning: Executes after normal termination of join point
@AfterThrowing: Executes after exception termination off
@Around: Begins execution before the jin point and user controls if to move and execute at end of join point. This is one of the most used advices.
Base Project
We will create a base project to work on it. This project will be a basic REST service. For our convenience we will only expose endpoints as GET requests so we can run it directly from browser. We will build the simplest room reservation system, where you can allocate a room to a user, or have the user vacate a room. Also create two singletons to manage the data.
public enum Rooms {
INSTANCE;
List<String> allRooms = new ArrayList<>();
List<String> availableRooms = new ArrayList<>();
private Rooms() {
this.allRooms.addAll(Arrays.asList("101", "102", "103", "104", "105",
"201", "202", "203", "204", "205", "301", "302", "303", "304", "305"));
this.availableRooms.addAll(allRooms);
}
public List<String> getAllRooms() {
return this.allRooms;
}
public List<String> getAvailableRooms() {
return this.availableRooms;
}
public String assignNextRoom() {
if (this.availableRooms.isEmpty()) {
return null;
}
final String room = this.availableRooms.remove(0);
return room;
}
public void takeRoom(final String roomName) {
this.availableRooms.remove(roomName);
}
public void freeRoom(final String roomName) {
this.availableRooms.add(roomName);
}
}public enum Guests {
INSTANCE;
Map<String, String> allGuests = new HashMap<>();
private Guests() {
}
public Map<String, String> getAllGuests() {
return allGuests;
}
public String checkinGuest(final String guestName) {
final String room = Rooms.INSTANCE.assignNextRoom();
if (room == null) {
return null;
}
this.allGuests.put(guestName, room);
return room;
}
public String checkoutGuest(final String guestName) {
if (this.allGuests.get(guestName) == null) {
return null;
}
Rooms.INSTANCE.freeRoom(this.allGuests.get(guestName));
return this.allGuests.remove(guestName);
}
}We built a service class on top of this.
@Slf4j
@Service
public class GuestServices {
public String checkIn(final String guestName) {
log.info("GuestServices::checkIn invoked...");
return Guests.INSTANCE.checkinGuest(guestName);
}
public String checkOut(final String guestName) {
log.info("GuestServices::checkOut invoked...");
return Guests.INSTANCE.checkoutGuest(guestName);
}
public List<RoomAssignment> getRooms() {
log.info("GuestServices::getRooms invoked...");
final List<RoomAssignment> rooms = new ArrayList<>();
final List<String> avlRooms = Rooms.INSTANCE.getAvailableRooms();
avlRooms.forEach(x -> {
rooms.add(new RoomAssignment(x, "-- OPEN --"));
});
final Map<String, String> filledRooms = Guests.INSTANCE.getAllGuests();
filledRooms.forEach((k, v) -> {
rooms.add(new RoomAssignment(v, k));
});
return rooms;
}
}And finally, here is the controller for REST service. Like I said before, implement all methods as GETs as that makes it easier to call from browser.
@Slf4j
@CrossOrigin
@RestController
@RequestMapping("/guest")
public class GuestController {
@Autowired
private GuestServices svc;
@GetMapping("/rooms")
public ResponseEntity<RoomResponse> getRooms() {
final RoomResponse resp = new RoomResponse();
final List<RoomAssignment> rooms = svc.getRooms();
resp.setRespCode(0);
resp.setRespMsg("SUCCESS");
resp.setRooms(rooms);
return ResponseEntity.ok().body(resp);
}
@GetMapping("/book/{name}")
public ResponseEntity<GuestResponse> bookRoom(@PathVariable String name) {
final GuestResponse resp = new GuestResponse();
final String svcresp = svc.checkIn(name.toLowerCase());
log.info("...Service called for checking in guest");
if (svcresp == null) {
resp.setRespCode(1);
resp.setRespMsg("No more rooms available...");
} else {
resp.setRespCode(0);
resp.setRespMsg("Room # allocated: " + svcresp);
}
return ResponseEntity.ok().body(resp);
}
/*
*
*/
@GetMapping("/vacate/{name}")
public ResponseEntity<GuestResponse> vacateRoom(@PathVariable String name) {
final GuestResponse resp = new GuestResponse();
final String svcresp = svc.checkOut(name.toLowerCase());
log.info("...Service called for cheking out guest");
resp.setRespCode(0);
resp.setRespMsg("Room # vacated: " + svcresp);
return ResponseEntity.ok().body(resp);
}
}Now that we have the base project defined, let’s start working on some examples for AOP using SpringBoot. Most of these we will use Service class to experiment.
Simple Pointcuts
We will start with writing some simple point cut examples. We will write an exact search on checkIn and write a before and after point cut advice for this.
/**
* Execution pointcut on a single method. Will execute for the method only
*/
@Pointcut("execution(public String checkIn(String))")
public void pointcutCheckinExecute() {}
@Before("pointcutCheckinExecute()")
public void logMethlogPointCut01() {
log.info("...Point Cut (BEFORE CHECKIN) triggered...");
}
@After("pointcutCheckinExecute()")
public void logMethlogPointCut02() {
log.info("...Point Cut (AFTER CHECKIN) triggered...");
}Let’s run this one and see what we get. We will try to book a room – it will trigger this method.
com.suturf.blog.aspect.ExamplePointcuts : ...Point Cut (BEFORE CHECKIN) triggered... com.suturf.blog.service.GuestServices : GuestServices::checkIn invoked... com.suturf.blog.aspect.ExamplePointcuts : ...Point Cut (AFTER CHECKIN) triggered... c.s.blog.controller.GuestController : ...Service finished for checking in guest
If you see, as expected it triggers the Before point cut before method execution and after point cut after the method execution completes.
Now let’s add one more point cut to the equation. We will add a point cut to trigger anytime a method in service class is invoked.
/*
* Let's create a pointcut to execute anytime any method in service class is accessed
*/
@Pointcut("within(com.suturf.blog.service.GuestServices)")
public void pointcutModelGetWithin() {}
@Before("pointcutModelGetWithin()")
public void logMethlogPointCut03(final JoinPoint joinPoint) {
log.info("...Point Cut (GUEST SERVICE ACCESSED) triggered..." + joinPoint.getSignature());
}With this in place, we will invoke the list rooms API.
com.suturf.blog.aspect.ExamplePointcuts : ...Point Cut (GUEST SERVICE ACCESSED) triggered...List com.suturf.blog.service.GuestServices.getRooms() com.suturf.blog.service.GuestServices : GuestServices::getRooms invoked... c.s.blog.controller.GuestController : ...Service finished for checking for rooms
So it executed a service method and the point cut triggered. List com.suturf.blog.service.GuestServices.getRooms() invoked.
Let’s write one more simple point cut. Let’s trigger the point cut whenever a method having ‘Room’ in the name is invoked. Also let’s try to use the After advices with Return and Throw and see the behavior.
/*
* All methods everywhere that has Room in method name
*/
@Pointcut("execution(* *..*Room*(..))")
public void pointcutAllWithRoom() {}
@Before("pointcutAllWithRoom()")
public void logAllRoomBefore(final JoinPoint joinPoint) {
log.info("...Point Cut (METHOD WITH ROOM ACCESSED - BEFORE) triggered..." + joinPoint.getSignature());
}
@AfterReturning("pointcutAllWithRoom()")
public void logAllRoomAfterReturn(final JoinPoint joinPoint) {
log.info("...Point Cut (METHOD WITH ROOM ACCESSED - AFTER RETURN) triggered..." + joinPoint.getSignature());
}
@AfterThrowing("pointcutAllWithRoom()")
public void logAllRoomAfterThrow(final JoinPoint joinPoint) {
log.info("...Point Cut (METHOD WITH ROOM ACCESSED - AFTER THROW) triggered..." + joinPoint.getSignature());
}We will execute the same API as before. However, in this case we expect additional point cuts to trigger.
com.suturf.blog.aspect.ExamplePointcuts : ...Point Cut (METHOD WITH ROOM ACCESSED - BEFORE) triggered...ResponseEntity com.suturf.blog.controller.GuestController.getRooms() com.suturf.blog.aspect.ExamplePointcuts : ...Point Cut (METHOD WITH ROOM ACCESSED - BEFORE) triggered...List com.suturf.blog.service.GuestServices.getRooms() com.suturf.blog.aspect.ExamplePointcuts : ...Point Cut (GUEST SERVICE ACCESSED) triggered...List com.suturf.blog.service.GuestServices.getRooms() com.suturf.blog.service.GuestServices : GuestServices::getRooms invoked... com.suturf.blog.aspect.ExamplePointcuts : ...Point Cut (METHOD WITH ROOM ACCESSED - AFTER RETURN) triggered...List com.suturf.blog.service.GuestServices.getRooms() c.s.blog.controller.GuestController : ...Service finished for checking for rooms com.suturf.blog.aspect.ExamplePointcuts : ...Point Cut (METHOD WITH ROOM ACCESSED - AFTER RETURN) triggered...ResponseEntity com.suturf.blog.controller.GuestController.getRooms()
Now this is more interesting. We have ‘Room’ in the name of methods in both Controller and Service. So the sequence in which the pointcuts triggered is as follows,
- BEFORE – com.suturf.blog.controller.GuestController.getRooms()
- BEFORE – com.suturf.blog.service.GuestServices.getRooms()
- AFTER RETURN – com.suturf.blog.service.GuestServices.getRooms()
- AFTER RETURN – com.suturf.blog.controller.GuestController.getRooms()
One thing to note here is that Exception point cut is not logged. This is because no exception triggered.
Annotation driven
To demonstrate this point cut, let’s create an annotation.
package com.suturf.blog.annotation;
import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;
@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface LogSomeMsg {
}This is a basic annotation interface. Now we will create a point cut to log a message when we encounter this annotation.
package com.suturf.blog.aspect;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;
import org.springframework.stereotype.Component;
import lombok.extern.slf4j.Slf4j;
@Slf4j
@Aspect
@Component
public class AnnotationDriven {
@Pointcut("@annotation(com.suturf.blog.annotation.LogSomeMsg)")
public void logDummyMessage() {}
@Before("logDummyMessage()")
public void beforeSpinSpinner(final JoinPoint joinPoint) {
log.info("...Point Cut (LOG DUMMY MESSAGE...) triggered..." + joinPoint.getSignature());
}
}That’s it. We are now ready to use this annotation on any method. Let’s check it out. I will add this also to getRooms in service.
@LogSomeMsg
public List<RoomAssignment> getRooms() {
...com.suturf.blog.aspect.ExamplePointcuts : ...Point Cut (METHOD WITH ROOM ACCESSED - BEFORE) triggered...ResponseEntity com.suturf.blog.controller.GuestController.getRooms() com.suturf.blog.aspect.AnnotationDriven : ...Point Cut (LOG DUMMY MESSAGE...) triggered...List com.suturf.blog.aspect.ExamplePointcuts : ...Point Cut (METHOD WITH ROOM ACCESSED - BEFORE) triggered...List com.suturf.blog.service.GuestServices.getRooms() com.suturf.blog.aspect.ExamplePointcuts : ...Point Cut (GUEST SERVICE ACCESSED) triggered...List com.suturf.blog.service.GuestServices.getRooms() com.suturf.blog.service.GuestServices : GuestServices::getRooms invoked... com.suturf.blog.aspect.ExamplePointcuts : ...Point Cut (METHOD WITH ROOM ACCESSED - AFTER RETURN) triggered...List com.suturf.blog.service.GuestServices.getRooms() c.s.blog.controller.GuestController : ...Service finished for checking for rooms com.suturf.blog.aspect.ExamplePointcuts : ...Point Cut (METHOD WITH ROOM ACCESSED - AFTER RETURN) triggered...ResponseEntity com.suturf.blog.controller.GuestController.getRooms()
Along with everything else before, annotation point cut also triggered. We got “(LOG DUMMY MESSAGE…) triggered…”. message as well
Use Case – Log Execution time
Finally we will look at one of the overused application for point cuts. We create advices to log execution times for all annotated methods. We again start with an annotation.
package com.suturf.blog.annotation;
import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;
@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface LogExecTime {
}Next we will create a @Around advice.
package com.suturf.blog.aspect;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.springframework.stereotype.Component;
import lombok.extern.slf4j.Slf4j;
@Slf4j
@Aspect
@Component
public class LoggingPointcut {
@Around("@annotation(com.suturf.blog.annotation.LogExecTime)")
public Object executionTime(final ProceedingJoinPoint point)
throws Throwable {
final long startTm = System.currentTimeMillis();
final Object object = point.proceed();
final long endTm = System.currentTimeMillis();
final StringBuilder str = new StringBuilder();
str.append("Execution time (ms): ").append(point.getSignature().getDeclaringTypeName());
str.append(":").append(point.getSignature().getName());
str.append(" >> ").append(endTm - startTm);
log.info(str.toString());
return object;
}
}Now the only thing left is to annotate the method where we need timing. Notice that in this we use a proceed method to move to the end of the method. So, we get a timing at the beginning, move to the end – which means execution completed and then capture a time again. Finally we return this.
Let’s add this to one of the methods in controller.
@GetMapping("/rooms")
@LogExecTime
public ResponseEntity<RoomResponse> getRooms() {Now we see a new log added to the mix. Viola, we have execution time.
com.suturf.blog.aspect.LoggingPointcut : Execution time (ms): com.suturf.blog.controller.GuestController:getRooms >> 12
Conclusion
This blog turned out to be much longer than I would have preferred. There is lot more of point cuts and variations in the constructs. Additional information can be read from Spring manuals. Ciao for now!