Logging aspect in RESTful web service – spring aop (log requests/responses)

• Logging request & response information is basic requirement of enterprise RESTFul web service.
• We will create RESTFul web service using Spring.
• We have already discussed what is aspect oriented programming.

RESTFul Service – Spring AOP Logging Aspect?

1. Create RESTFul web service using spring framework.
   • Create REST resource BookingController to book hotel & retrieve booking information
   • POST resource hotel booking taking required customer information
   • GET resource to simulate to retrieval of hotel booking
2. Create a logging aspect.
   • Create logging aspect using spring aop
   • Create join points
   • Create pointcut expressions
3. Usage of pointcut expressions with following advices
   • Before advice
   • After advice
   • Around advice
   • AfterThrowing
   • AfterReturning
4. Generate request response logs.
   • Log request & response information using logging framework like Log4J.

Program – Logging aspect in RESTful web service using spring aop

1.) Spring AOP Logging Aspect:

• Create a logging aspect LoggingHandler using spring aop
• Create point cut expression
  1. controller
  2. allMethod
  3. loggingPublicOperation
  4. logAnyFunctionWithinResource

import java.util.Arrays;
import java.util.Enumeration;

import javax.servlet.http.HttpServletRequest;

import org.apache.commons.lang3.builder.ReflectionToStringBuilder;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.AfterThrowing;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

@Aspect
@Component
public class LoggingHandler {

 Logger log = LoggerFactory.getLogger(this.getClass());

 @Pointcut("within(@org.springframework.stereotype.Controller *)")
 public void controller() {
 }

 @Pointcut("execution(* *.*(..))")
 protected void allMethod() {
 }

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

 @Pointcut("execution(* *.*(..))")
 protected void loggingAllOperation() {
 }

 @Pointcut("within(org.learn.log..*)")
 private void logAnyFunctionWithinResource() {
 }

 //before -> Any resource annotated with @Controller annotation 
 //and all method and function taking HttpServletRequest as first parameter
 @Before("controller() && allMethod() && args(..,request)")
 public void logBefore(JoinPoint joinPoint, HttpServletRequest request) {

  log.debug("Entering in Method :  " + joinPoint.getSignature().getName());
  log.debug("Class Name :  " + joinPoint.getSignature().getDeclaringTypeName());
  log.debug("Arguments :  " + Arrays.toString(joinPoint.getArgs()));
  log.debug("Target class : " + joinPoint.getTarget().getClass().getName());

  if (null != request) {
   log.debug("Start Header Section of request ");
   log.debug("Method Type : " + request.getMethod());
   Enumeration headerNames = request.getHeaderNames();
   while (headerNames.hasMoreElements()) {
    String headerName = headerNames.nextElement();
    String headerValue = request.getHeader(headerName);
    log.debug("Header Name: " + headerName + " Header Value : " + headerValue);
   }
   log.debug("Request Path info :" + request.getServletPath());
   log.debug("End Header Section of request ");
  }
 }
 //After -> All method within resource annotated with @Controller annotation 
 // and return a  value
 @AfterReturning(pointcut = "controller() && allMethod()", returning = "result")
 public void logAfter(JoinPoint joinPoint, Object result) {
  String returnValue = this.getValue(result);
  log.debug("Method Return value : " + returnValue);
 }
 //After -> Any method within resource annotated with @Controller annotation 
 // throws an exception ...Log it
 @AfterThrowing(pointcut = "controller() && allMethod()", throwing = "exception")
 public void logAfterThrowing(JoinPoint joinPoint, Throwable exception) {
  log.error("An exception has been thrown in " + joinPoint.getSignature().getName() + " ()");
  log.error("Cause : " + exception.getCause());
 }
 //Around -> Any method within resource annotated with @Controller annotation 
 @Around("controller() && allMethod()")
 public Object logAround(ProceedingJoinPoint joinPoint) throws Throwable {
  
  long start = System.currentTimeMillis();
  try {
   String className = joinPoint.getSignature().getDeclaringTypeName();
   String methodName = joinPoint.getSignature().getName();
   Object result = joinPoint.proceed();
   long elapsedTime = System.currentTimeMillis() - start;
   log.debug("Method " + className + "." + methodName + " ()" + " execution time : "
     + elapsedTime + " ms");
  
   return result;
  } catch (IllegalArgumentException e) {
   log.error("Illegal argument " + Arrays.toString(joinPoint.getArgs()) + " in "
     + joinPoint.getSignature().getName() + "()");
   throw e;
  }
 }
 private String getValue(Object result) {
  String returnValue = null;
  if (null != result) {
   if (result.toString().endsWith("@" + Integer.toHexString(result.hashCode()))) {
    returnValue = ReflectionToStringBuilder.toString(result);
   } else {
    returnValue = result.toString();
   }
  }
  return returnValue;
 }
}

2.) Booking controller resource:

import java.text.DateFormat;
import java.util.Date;
import java.util.Locale;
import java.util.UUID;

import javax.servlet.http.HttpServletRequest;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Controller;
import org.springframework.ui.Model;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RequestMethod;
import org.springframework.web.bind.annotation.RequestParam;

/**
 * Handles requests for the application home page.
 */
@Controller
@RequestMapping("/hotel")
public class BookingController {
  
 private static final Logger logger = LoggerFactory.getLogger(BookingController.class);
 
 /**
  * Simply selects the home view to render by returning its name.
  */
 @RequestMapping(value = "/", method = RequestMethod.GET)
 public String home(Locale locale, Model model) {
  logger.info("Welcome home! The client locale is {}.", locale);
  
  Date date = new Date();
  DateFormat dateFormat = DateFormat.getDateTimeInstance(DateFormat.LONG, DateFormat.LONG, locale);
  
  String formattedDate = dateFormat.format(date);
  
  model.addAttribute("serverTime", formattedDate );
  
  return "hotel";
 }

 @RequestMapping(value="/book", method=RequestMethod.POST)
    public String bookHotel(
      @RequestParam(value = "name",required=false) String name,
            @RequestParam(value = "city", required = false) String city,
            @RequestParam(value = "purpose",required=false) String purpose,
            @RequestParam(value = "idproof", required = false) String idproof,
            Model model,  HttpServletRequest request){
  
  //Save the required information in data base
  //......
  //......
  //Send the response back
  model.addAttribute("name", name );
  model.addAttribute("city", city );
  model.addAttribute("purpose", purpose );
  model.addAttribute("idproof", idproof );
  
  return "customerDetails";
 }
 
 @RequestMapping(value="/book", method=RequestMethod.GET)
    public String bookHotel(
      @RequestParam(value = "id",required=false) String id,
      Model model,  HttpServletRequest request){
  
  //get the required information in data base for customer Id
  //......
  //......
  
  //suppose we get these value from database
  String randomName = UUID.randomUUID().toString().substring(0,4);
  String randomCity = UUID.randomUUID().toString().substring(0,4);
  String randomPurpose = UUID.randomUUID().toString().substring(0,4);
  String randomIdProof = UUID.randomUUID().toString().substring(0,4);
   
  //Send the response back
  model.addAttribute("name", "Name "+randomName );
  model.addAttribute("city", "City "+randomCity );
  model.addAttribute("purpose", "Purpose "+randomPurpose);
  model.addAttribute("idproof", "IdProof "+randomIdProof );
  
  return "customerDetails";
 }
}

3.) Web.xml:

<?xml version="1.0" encoding="UTF-8"?>
<web-app version="2.5" xmlns="http://java.sun.com/xml/ns/javaee"
 xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
 xsi:schemaLocation="http://java.sun.com/xml/ns/javaee http://java.sun.com/xml/ns/javaee/web-app_2_5.xsd">

 <!-- The definition of the Root Spring Container shared by all Servlets and Filters -->
 <context-param>
  <param-name>contextConfigLocation</param-name>
  <param-value>/WEB-INF/spring/root-context.xml</param-value> 
  <!-- <param-value>/WEB-INF/spring/appServlet/servlet-context.xml</param-value>  -->
 </context-param>
 
 <!-- Creates the Spring Container shared by all Servlets and Filters -->
 <listener>
  <listener-class>org.springframework.web.context.ContextLoaderListener</listener-class>
 </listener>

 <!-- Processes application requests -->
 <servlet>
  <servlet-name>appServlet</servlet-name>
  <servlet-class>org.springframework.web.servlet.DispatcherServlet</servlet-class>
  <init-param>
   <param-name>contextConfigLocation</param-name>
   <param-value>/WEB-INF/spring/appServlet/servlet-context.xml</param-value>
  </init-param>
  <load-on-startup>1</load-on-startup>
 </servlet>
  
 <servlet-mapping>
  <servlet-name>appServlet</servlet-name>
  <url-pattern>/</url-pattern>
 </servlet-mapping>

</web-app>

Our server application is deployed in local machine so “localhost” is our machine name and at port 9095. Change your ip and port to access the resources of BookingController. Besides, do take care of context path where you have deployed your application.
The URL to access the resource should look like
http://<IP Address or machine name>:<port number>/log/hotel/

Spring Logging Aspect execution results:

Default Home Page

http://localhost:9095/log/hotel/
Logs are :

INFO : Welcome home! The client locale is en_US.
DEBUG: Method org.learn.log.BookingController.home () execution time : 1 ms
DEBUG: Method Return value : hotel

Post request RESTFul Service 

http://localhost:9095/log/hotel/book
Logs are :

DEBUG: Entering in Method : bookHotel
DEBUG: Class Name : org.learn.log.BookingController
DEBUG: Arguments : [Scott, Customer CityName, Personal, Security Number, {}, org.apache.catalina.connector.RequestFacade@7886596e]
DEBUG: Target class : org.learn.log.BookingController
DEBUG: Start Header Section of request
DEBUG: Method Type : POST
DEBUG: Header Name: host Header Value : localhost:9095
DEBUG: Header Name: connection Header Value : keep-alive
DEBUG: Header Name: content-length Header Value : 0
DEBUG: Header Name: user-agent Header Value : Mozilla/5.0 (Windows NT 6.3; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/45.0.2454.101 Safari/537.36
DEBUG: Header Name: cache-control Header Value : no-cache
DEBUG: Header Name: origin Header Value : chrome-extension://mkhojklkhkdaghjjfdnphfphiaiohkef
DEBUG: Header Name: accept Header Value : */*
DEBUG: Header Name: accept-encoding Header Value : gzip, deflate
DEBUG: Header Name: accept-language Header Value : en-US,en;q=0.8
DEBUG: Request Path info :/hotel/book
DEBUG: End Header Section of request
DEBUG: Method org.learn.log.BookingController.bookHotel () execution time : 148 ms
DEBUG: Method Return value : customerDetails

GET Request – RESTFul WebService

http://localhost:9095/log/hotel/book?id=1
Logs are :

DEBUG: Entering in Method : bookHotel
DEBUG: Class Name : org.learn.log.BookingController
DEBUG: Arguments : [1, {}, org.apache.catalina.connector.RequestFacade@777d0dd6]
DEBUG: Target class : org.learn.log.BookingController
DEBUG: Start Header Section of request
DEBUG: Method Type : GET
DEBUG: Header Name: accept Header Value : image/jpeg, application/x-ms-application, image/gif, application/xaml+xml, image/pjpeg, application/x-ms-xbap, */*
DEBUG: Header Name: accept-language Header Value : en-US
DEBUG: Header Name: ua-cpu Header Value : AMD64
DEBUG: Header Name: accept-encoding Header Value : gzip, deflate
DEBUG: Header Name: user-agent Header Value : Mozilla/5.0 (Windows NT 6.2; Win64; x64; Trident/7.0; MASPJS; rv:11.0) like Gecko
DEBUG: Header Name: host Header Value : localhost:9095
DEBUG: Header Name: connection Header Value : Keep-Alive
DEBUG: Request Path info :/hotel/book
DEBUG: End Header Section of request
DEBUG: Method org.learn.log.BookingController.bookHotel () execution time : 8 ms
DEBUG: Method Return value : customerDetails

We can download the complete code. Refer ReadMe.md file under project directory for more details. In our pom we have kept commonly used jars required to develop any web application.

Code: Logging aspect RESTFul web service spring aop