Implementing a Method Trace Infrastructure With Spring Boot and AspectJ

In our applications, the ability to get stack trace of methods can be a lifesaver. Having input-output parameter values and time spent in methods can make it easier to find the problem. In this post, we will look at how to implement a starting point for a method trace infrastructure using Spring Boot, AspectJ, and Threadlocal. 

You may also like: Understanding and Leveraging the Java Stack Trace

In this example, I used :

• Spring Boot Starter Web 2.1.7
• Java 1.8 +
• AspectJ 1.8
• Maven 3.2

1. Overview

In this tutorial, we will prepare a simple REST service that will retrieve details about a book in a bookstore. Then, we will add a ThreadLocal model that will keep the stack structure throughout the thread life. And lastly, we will add an aspect to cut the methods in the call stack for the purpose of getting input/output parameter values. Let's get started!

Project Structure

2. Maven Dependencies

• Spring Boot Starter Web — for RESTful services using Spring MVC
• Spring — for Aspect capabilities
• The AspectJ weaver introduces advice to Java classes
• Apache Commons Lang — for string utilities

    <parent>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-parent</artifactId>
        <version>2.1.7.RELEASE</version>
    </parent>

<properties>
        <java.version>1.8</java.version>
    </properties>

<dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
            <version>2.1.7.RELEASE</version>
        </dependency>
        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-aop</artifactId>
            <version>5.0.9.RELEASE</version>
        </dependency>
        <dependency>
            <groupId>org.aspectj</groupId>
            <artifactId>aspectjweaver</artifactId>
            <version>1.8.9</version>
        </dependency>
        <dependency>
            <groupId>org.apache.commons</groupId>
            <artifactId>commons-lang3</artifactId>
            <version>3.8.1</version>
        </dependency>
    </dependencies>

3. Implementation

Create a Spring Boot Application

You can either use these templates to create a simple Spring Boot Application for a step-by-step implementation, or you can directly download the final project here.

For IntelliJ:

https://www.javadevjournal.com/spring-boot/spring-boot-application-intellij/

For Eclipse:

https://dzone.com/articles/building-your-first-spring-boot-web-application-ex

Simple Rest Service and Methods

First, we will create our services. We will get the book item number as an input parameter and give Title, Price, and Content information as a service output.

We will have three simple services:

PriceService:

package com.example.demo.service;

import org.springframework.stereotype.Service;

@Service
public class PriceService {

    public double getPrice(int itemNo){
            switch (itemNo) {
                case 1 :
                    return 10.d;
                case 2 :
                    return 20.d;
                default:
                    return 0.d;
            }
    }

}

CatalogueService:

package com.example.demo.service;

import org.springframework.stereotype.Service;

@Service
public class CatalogueService {

    public String getContent(int itemNo){
        switch (itemNo) {
            case 1 :
                return "Lorem ipsum content 1.";
            case 2 :
                return "Lorem ipsum content 2.";
            default:
                return "Content not found.";
        }
    }


    public String getTitle(int itemNo){
        switch (itemNo) {
            case 1 :
                return "For whom the bell tolls";
            case 2 :
                return "Of mice and men";
            default:
                return "Title not found.";
        }
    }

}

BookInfoService:

package com.example.demo.service;

import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Service;

@Service
public class BookInfoService {

    @Autowired
    PriceService priceService;

    @Autowired
    CatalogueService catalogueService;

    public String getBookInfo(int itemNo){
        StringBuilder sb = new StringBuilder();
        sb.append(" Title :" + catalogueService.getTitle(itemNo));
        sb.append(" Price:" + priceService.getPrice(itemNo));
        sb.append(" Content:" + catalogueService.getContent(itemNo));
        return sb.toString();
    }
}

BookController: This is our REST controller used to create a RET service that retrieves book info. We will prepare a TraceMonitor service to print stack trace later.

package com.example.demo.controller;

import com.example.demo.service.BookInfoService;
import com.example.demo.trace.TraceMonitor;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.PathVariable;
import org.springframework.web.bind.annotation.RestController;

@RestController
public class BookController {

    @Autowired
    BookInfoService bookInfoService;

    @Autowired
    TraceMonitor traceMonitor;

    @GetMapping("/getBookInfo/{itemNo}")
    public String getBookInfo(@PathVariable int itemNo) {
        try{
            return bookInfoService.getBookInfo(itemNo);
        }finally {
            traceMonitor.printTrace();
        }
    }

}

Our REST controller is ready to use. If we comment out the traceMonitor.printTrace() method, which we haven't implemented yet, and run our application with a class annotated by  @SpringBootApplication:

package com.example.demo;

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;

@SpringBootApplication
public class DemoApplication {

    public static void main(String[] args) {
        SpringApplication.run(DemoApplication.class, args);
    }

}

http://localhost:8080/getBookInfo/2

> Title :Of mice and men Price:20.0 Content:Lorem ipsum content 2.

ThreadLocal Model

Now we will prepare our Method object that will hold information for any method call. Later, we will prepare the stack structure and ThreadLocal object that will keep stack structure throughout the life of the thread.

Method: This will be our model object that will keep all the details about the execution of a method. It contains input/output parameters of a method, time spent in the method, and a methodList object, which is a list of methods called directly from the method.

package com.example.demo.util.log.standartlogger;

import java.util.List;

public class Method {

private String methodName;
private String input;
private List<Method> methodList;
private String output;
private Long timeInMs;

public Long getTimeInMs() {
return timeInMs;
}

public void setTimeInMs(Long timeInMs) {
this.timeInMs = timeInMs;
}

public String getInput() {
return input;
}

public void setInput(String input) {
this.input = input;
}

public String getOutput() {
return output;
}

public void setOutput(String output) {
this.output = output;
}

public List<Method> getMethodList() {
return methodList;
}

public void setMethodList(List<Method> methodList) {
this.methodList = methodList;
}

public String getMethodName() {
return methodName;
}

public void setMethodName(String methodName) {
this.methodName = methodName;
}

}

ThreadLocalValues: Keeps trace information for the main method. Method mainMethod contains the  List<Method>methodList object, which contains submethods called from the main method.

 Deque<Method>methodStack is the object that keeps the method call stack. It lives throughout the thread's life. When a submethod is called, a Method object is pushed to the methodStack, and when a submethod returns, the top Method object is popped from the methodStack.

package com.example.demo.util.log.standartlogger;


import java.util.Deque;

public class ThreadLocalValues {

private Deque<Method> methodStack;
private Method mainMethod;

public ThreadLocalValues() {
super();
}

public Method getMainMethod() {
return mainMethod;
}

public void setMainMethod(Method mainMethod) {
this.mainMethod = mainMethod;
}

public Deque<Method> getMethodStack() {
return methodStack;
}

public void setMethodStack(Deque<Method> methodStack) {
this.methodStack = methodStack;
}

}

LoggerThreadLocal: This class keeps a ThreadLocal object of ThreadLocalValues. The object lives throughout the thread's life.

package com.example.demo.util.log.standartlogger;


import java.util.ArrayDeque;
import java.util.Deque;

public class LoggerThreadLocal {

static final ThreadLocal<ThreadLocalValues> threadLocal = new ThreadLocal<>();

private LoggerThreadLocal() {
super();
}

public static void setMethodStack(Deque<Method> methodStack) {
ThreadLocalValues threadLocalValues = threadLocal.get();
if (null == threadLocalValues) {
threadLocalValues = new ThreadLocalValues();
}
threadLocalValues.setMethodStack(methodStack);
threadLocal.set(threadLocalValues);
}

public static void setMainMethod(Method mainMethod){
ThreadLocalValues threadLocalValues = threadLocal.get();
if (null == threadLocalValues) {
threadLocalValues = new ThreadLocalValues();
}
threadLocalValues.setMainMethod(mainMethod);
threadLocal.set(threadLocalValues);
}

public static Method getMainMethod() {
if (threadLocal.get() == null) {
return null;
}
return threadLocal.get().getMainMethod();
}

public static Deque<Method> getMethodStack() {
if (threadLocal.get() == null) {
setMethodStack(new ArrayDeque<>());
}
return threadLocal.get().getMethodStack();
}

}

Aspect Implementations:

TraceMonitor: This class is the configuration class of our aspect. In this class, we define our pointcuts where the aspect cuts the code flow. Our pointcut defines all the methods in all the classes whose name ends with the word "Service."

 @Pointcut(value = "execution(* com.example.demo.service.*Service.*(..))") 

pushStackInBean: This is the method that will push the current method into the method stack before the execution of the methods in the pointcut.

popStackInBean: This is the method that will remove the top method in the stack after the return of the method in the pointcut.

printTrace: This is the method that will print the threadLocal value (mainMethod) in a JSON format.

package com.example.demo.trace;


import java.util.ArrayList;

import com.example.demo.util.log.standartlogger.LoggerThreadLocal;
import com.example.demo.util.log.standartlogger.Method;
import com.fasterxml.jackson.core.JsonProcessingException;
import com.fasterxml.jackson.databind.ObjectMapper;
import org.apache.commons.lang3.StringUtils;
import org.apache.commons.lang3.exception.ExceptionUtils;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;
import org.springframework.context.annotation.Configuration;
import org.springframework.stereotype.Service;

@Aspect
@Service
@Configuration
public class TraceMonitor {

    @Pointcut(value = "execution(* com.example.demo.service.*Service.*(..))")
    private void executionInService() {
        //do nothing, just for pointcut def
    }

    @Before(value = "executionInService()")
    public void pushStackInBean(JoinPoint joinPoint) {
        pushStack(joinPoint);
    }

    @AfterReturning(value = "executionInService()", returning = "returnValue")
    public void popStackInBean(Object returnValue) {
        popStack(returnValue);
    }

    ObjectMapper mapper = new ObjectMapper();

    private void pushStack(JoinPoint joinPoint) {
            Method m = new Method();
            m.setMethodName(StringUtils.replace(joinPoint.getSignature().toString(), "com.example.demo.service.", ""));
            String input = getInputParametersString(joinPoint.getArgs());
            m.setInput(input);
            m.setTimeInMs(Long.valueOf(System.currentTimeMillis()));
            LoggerThreadLocal.getMethodStack().push(m);
    }

    private String getInputParametersString(Object[] joinPointArgs) {
        String input;
        try {
            input = mapper.writeValueAsString(joinPointArgs);
        } catch (Exception e) {
            input = "Unable to create input parameters string. Error:" + e.getMessage();
        }
        return input;
    }


    private void popStack(Object output) {
        Method childMethod = LoggerThreadLocal.getMethodStack().pop();
        try {
            childMethod.setOutput(output==null?"": mapper.writeValueAsString(output));
        } catch (JsonProcessingException e) {
            childMethod.setOutput(e.getMessage());
        }
        childMethod.setTimeInMs(Long.valueOf(System.currentTimeMillis() - childMethod.getTimeInMs().longValue()));
        if (LoggerThreadLocal.getMethodStack().isEmpty()) {
            LoggerThreadLocal.setMainMethod(childMethod);
        } else {
            Method parentMethod = LoggerThreadLocal.getMethodStack().peek();
            addChildMethod(childMethod, parentMethod);
        }
    }

    private void addChildMethod(Method childMethod, Method parentMethod) {
        if (parentMethod != null) {
            if (parentMethod.getMethodList() == null) {
                parentMethod.setMethodList(new ArrayList<>());
            }
            parentMethod.getMethodList().add(childMethod);
        }
    }

    public void printTrace() {
        try {
            StringBuilder sb = new StringBuilder();
            sb.append("\n<TRACE>\n").append(mapper.writerWithDefaultPrettyPrinter().writeValueAsString(LoggerThreadLocal.getMainMethod()));
            sb.append("\n</TRACE>");
            System.out.println(sb.toString());
        } catch (JsonProcessingException e) {
            StringUtils.abbreviate(ExceptionUtils.getStackTrace(e), 2000);

        }
    }
}

3. Testing and Printing Stack

When we run our Spring Boot application and send a get request:

http://localhost:8080/getBookInfo/2

The return will be:

> Title:Of mice and men Price:20.0 Content:Lorem ipsum content 2.

Note: If you commented traceMonitor.printTrace() before, don't forget to uncomment it.

And the console output will be:

<TRACE>
{
  "methodName": "String service.BookInfoService.getBookInfo(int)",
  "input": "[2]",
  "methodList": [
    {
      "methodName": "String service.ContentService.getTitle(int)",
      "input": "[2]",
      "output": "\"Of mice and men\"",
      "timeInMs": 3
    },
    {
      "methodName": "Double service.PriceService.getPrice(int)",
      "input": "[2]",
      "output": "20.0",
      "timeInMs": 1
    },
    {
      "methodName": "String service.ContentService.getContent(int)",
      "input": "[2]",
      "output": "\"Lorem ipsum content 2.\"",
      "timeInMs": 0
    }
  ],
  "output": "\" Title :Of mice and men Price:20.0 Content:Lorem ipsum content 2.\"",
  "timeInMs": 6
}
</TRACE>

As we can easily keep track of the method flow:

•  getBookInfo method is called with input 2

•  getBookInfo calls getTitle  method with input 2

•  getTitle returns with output "Of mice and men" in 3 ms.

•  getBookInfo calls getPrice  with input 2

•  getPrice returns with output 20.0 in 1 ms.

•  getBookInfo calls getContent  with input 2

•  getContent returns with output "Lorem ipsum content 2." in 0 ms.

•  getBookInfo method returns with output "Title :Of mice and men Price:20.0 Content:Lorem ipsum content 2." in 6 ms.

Our trace implementation worked for our simple REST service call.

Further improvements should be:

• Exception handling with @AfterThrowing if any method gets an exception
• Open/close trace mechanism with a cacheable method that reads the traceable method list from a service or a database.
• Using a logger implementation (sl4j) to print the trace into a separate log file

You can find the complete Maven project with code examples on this GitHub repository.

Further Reading

Understanding and Leveraging the Java Stack Trace

Java Concurrency: Thread Confinement