AspectJ component for my services audit logger

This is a blog that will leverage the advantages of AspectJ aspect oriented programming concept in solving a very basic problem of auditing the visitors to your service and the response times. These parameters are very important when we want to do some operations around these.

Pre-requisite for AspectJ in your pom.xml

 <!-- Spring AspectJ -->
 <dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-aspects</artifactId>
    <version>${org.springframework-version}</version>
    <scope>compile</scope>
 </dependency>
 <dependency>
    <groupId>org.aspectj</groupId>
    <artifactId>aspectjweaver</artifactId>
    <version>${org.aspectj-version}</version>
    <scope>compile</scope>
 </dependency>
 <dependency>
    <groupId>org.aspectj</groupId>
    <artifactId>aspectjrt</artifactId>
    <version>${org.aspectj-version}</version>
 </dependency>
 <dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-aop</artifactId>
    <version>${org.springframework-version}</version>
 </dependency>
 <dependency>
    <groupId>cglib</groupId>
    <artifactId>cglib</artifactId>
    <version>3.1</version>
 </dependency>

In your application context add the configuration as per the standard aop proxy. You should also include component-scan and annotation-driven.

<!-- Aspects -->
 <aop:aspectj-autoproxy proxy-target-class="true"/>

Here is the actual code that will intercept around the public calls  in controller. It will print the service url, method, parameters and arguments. We can also obtain the user from the session context.

/**
 * @author Rahul Vishwakarma
 * This class will log all the service calls made to the Generic Application 
 * relying on the @Around advice
 * Ref: http://docs.spring.io/spring/docs/3.0.x/spring-framework-reference/html/aop.html#aop-understanding-aop-proxies 
 */
@Component
@Aspect
public class GenericLoggerAspect {
 /** Logger for this class and subclasses */
 private static final Logger log = LoggerFactory.getLogger(RhlLoggerAspect.class);
 
 public static ConcurrentHashMap<String,RequestData> responseTime = new ConcurrentHashMap<String,RequestData>();
 
 @Autowired 
 Utility utility;
/**
 * Inner class for request info
 * @author Rahul
 *
 */
 public class RequestInfo{
 public int responseTimeMills = 0;
 public Date accessTime = null;
 public String urlPath;
 public String requestType;
 public String args;
 }
 /**
 * Inner class for Data capturing request information
 * @author Rahul
 *
 */
 public class RequestData {
   public RequestInfo requestInfo;
   public String api;
   public UserInfo userInfo;
 
   public RequestData(RequestInfo requestInfo,UserInfo userInfo,String methodSignature){
   this.requestInfo = requestInfo;
   this.userInfo = userInfo;
   this.api = methodSignature;
   }
 }

/**
 * User and client related info
 * @author Rahul
 *
 */
 public class UserInfo{
   public String userName;
   public int userId;
   public String sessionId;
   public String role;
   public String clientIp;
 }
 
 private String getRepresentation(Object [] params){
   StringBuilder sb = new StringBuilder();
   if(params!=null)
   {
   String value = null;
   for(int i=0;i<params.length;i++){
   value = params[i] + ",";
   if(value.contains("@")){
     value = "";
   }
     sb.append(value);
   }
    if(sb.length()>0)
    return sb.substring(0, sb.length() - 1);
  }
  return sb.toString();
}
enum IssueType{
  ISSUE_URL_SUFFIX, OTHER, NONE
}
@Around("execution(@*..RequestMapping * * (..))")
public Object log_around(ProceedingJoinPoint pjp) throws Throwable {
 
  Object obj = null;
  IssueType issueType = IssueType.NONE;
  String error="Error in GenericLoggerAspect";
 try{
  String methodSignature = pjp.getSignature()+"";
  StringBuffer args = new StringBuffer(); //getRepresentation(pjp.getArgs());
 
  //Append arguments
  Object[] arg = pjp.getArgs();
  for (int i = 0; i < arg.length; i++) {
    args.append(arg[i]).append(",");
  }
  if (arg.length > 0) {
   args.deleteCharAt(args.length() - 1);
  }
 
  log.info("\tSTART {}-{}", methodSignature+" ["+Thread.currentThread().getId()+"]",args.toString());

  UserInfo userInfo = new UserInfo();
  UserSecure userSecure = utility.getUserInfo();
  if(userSecure != null){
   userInfo.clientIp = userSecure.getClientIp();
   userInfo.userId = userSecure.getUserId();
   userInfo.sessionId = userSecure.getSessionId();
   userInfo.userName = userSecure.getUserName();
  if(userSecure.getAuthorities() != null)
   userInfo.role = userSecure.getAuthorities().toString();
  }
  ServletRequestAttributes sra = (ServletRequestAttributes)RequestContextHolder.getRequestAttributes();
 
  String urlPath=""; 
 
  if(sra!=null){
    HttpServletRequest req = sra.getRequest();
  if(req!=null){
    urlPath = req.getServletPath();
  } 
 }
 
 long start = System.currentTimeMillis();
 if(urlPath.endsWith("/")){
   issueType = IssueType.ISSUE_URL_SUFFIX;
   obj = null;
 } else
   obj = pjp.proceed();
 
 String requestType = "ajax";
 if(obj!=null && (obj instanceof ModelAndView)){
   requestType = "page";
 }
 int elapsedTime = (int) (System.currentTimeMillis() - start); 
 RequestInfo requestInfo = new RequestInfo();
 requestInfo.accessTime = (new Date());
 requestInfo.requestType = (requestType);
 requestInfo.responseTimeMills = (elapsedTime);
 requestInfo.urlPath = (urlPath);
 requestInfo.args = (args.toString());
 
 RequestData requestData = new RequestData(requestInfo, userInfo,methodSignature);
 log.info(userInfo.sessionId + " REQ {} by "+userInfo.userName +"@"+userInfo.clientIp+", time {} mills; args ["+args.toString()+"]", urlPath + " ["+ Thread.currentThread().getId() +"]" , elapsedTime);
 responseTime.put(methodSignature, requestData);
 //addUserAuditLog(requestData);
 
 }catch(Exception ex){
 issueType = IssueType.OTHER;
 error = ex.getMessage();
 log.error(ex.getMessage());
}
 
if(obj==null){
 switch(issueType){
 case ISSUE_URL_SUFFIX:throw new GenericException("URL ends with trailling /"); 
 case OTHER:throw new GenericException(error);
 default:
 break;
 } 
}
return obj;
}
/**
 * @param exceptions
 */
@AfterThrowing(pointcut="execution(public * com.generic.controller.*.*(..))",throwing="ex") 
 public void MethodError(Exception ex){ 
   log.error("@Exception {}", ex.toString()); 
 } 
 
@Pointcut("execution(public * *(..))")
private void anyPublicOperation() {
   log.info("Testing the public Execution call");
 }
}

When we run the system we expect the following response in the log which does the @Around joint point.

Before:

17-Jul-2014 03:25:35,067-INFO – GenericLoggerAspect:130 –       START List com.humesis.generic.controller.UserController.getUsers(HttpServletResponse)

After:

17-Jul-2014 03:25:35,106-INFO – GenericLoggerAspect:176 – 674B8F114926E5A3BB143E7126D828C7 REQ /users [28] by rahul@0:0:0:0:0:0:0:1, time 36 mills; args [HttpSessionSecurityContextRepository]

This data can Asynchronously be audited or logged for generating the access pattern or hotspots in the service access.

 

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s