Mastering Request Logging with Spring AOP: A Complete Guide

During integration testing, mismatched request parameters and missing calls caused frequent debugging failures, prompting the need for a request‑log aspect to capture input data, verify method invocation, and provide evidence for troubleshooting.

Introduction

This article is practical; it does not explain AOP fundamentals in depth, only briefly introduces relevant concepts.

What is AOP?

Aspect‑Oriented Programming complements OOP by handling cross‑cutting concerns such as transaction management , authorization , caching , and logging . AOP separates core business logic from these concerns, improving modularity and maintainability.

Centralizes a specific cross‑cutting logic.

Allows easy addition or removal of concerns.

Low intrusiveness; enhances code readability and maintainability, making request‑log printing straightforward.

Using AOP with Annotations

@Aspect

– declares the class as an aspect.

Pointcut annotation: @Pointcut – defines a reusable pointcut expression.

Advice annotations: @Before – executes before the pointcut. @After – executes after the pointcut. @AfterReturning – runs after successful return, allowing result processing. @AfterThrowing – runs when an exception is thrown. @Around – surrounds the pointcut, executing code before and after.

Implementing a Request‑Log Aspect

Define the pointcut with @Pointcut.

@Pointcut("execution(* your_package.controller..*(..))")
public void requestServer() {}

The pointcut targets all methods in the controller package. The pointcut name can be referenced in advice annotations.

Log request details before controller execution.

@Before("requestServer()")
public void doBefore(JoinPoint joinPoint) {
    ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
    HttpServletRequest request = attributes.getRequest();
    LOGGER.info("===============================Start========================");
    LOGGER.info("IP                : {}", request.getRemoteAddr());
    LOGGER.info("URL               : {}", request.getRequestURL().toString());
    LOGGER.info("HTTP Method       : {}", request.getMethod());
    LOGGER.info("Class Method      : {}.{}", joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName());
}

This prints the caller IP, request URL, HTTP method, and the invoked class‑method.

Capture request parameters and execution time with @Around.

@Around("requestServer()")
public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
    long start = System.currentTimeMillis();
    Object result = proceedingJoinPoint.proceed();
    LOGGER.info("Request Params    : {}", getRequestParams(proceedingJoinPoint));
    LOGGER.info("Result            : {}", result);
    LOGGER.info("Time Cost         : {} ms", System.currentTimeMillis() - start);
    return result;
}

This logs the input parameters, the method result, and the time taken.

Utility method to retrieve parameters.

private Map<String, Object> getRequestParams(ProceedingJoinPoint proceedingJoinPoint) {
    Map<String, Object> requestParams = new HashMap<>();
    // Parameter names
    String[] paramNames = ((MethodSignature) proceedingJoinPoint.getSignature()).getParameterNames();
    // Parameter values
    Object[] paramValues = proceedingJoinPoint.getArgs();
    for (int i = 0; i < paramNames.length; i++) {
        Object value = paramValues[i];
        // Handle file uploads
        if (value instanceof MultipartFile) {
            MultipartFile file = (MultipartFile) value;
            value = file.getOriginalFilename();
        }
        requestParams.put(paramNames[i], value);
    }
    return requestParams;
}

Parameters passed via @PathVariable or @RequestParam are manually mapped; file objects are reduced to their original filenames.

Log after method execution.

@After("requestServer()")
public void doAfter(JoinPoint joinPoint) {
    LOGGER.info("===============================End========================");
}

No business logic is performed here; it simply marks the end of the request.

High‑Concurrency Optimizations

To avoid interleaved log lines under heavy load, consolidate all request information into a single object and serialize it.

@Data
public class RequestInfo {
    private String ip;
    private String url;
    private String httpMethod;
    private String classMethod;
    private Object requestParams;
    private Object result;
    private Long timeCost;
}

@Around("requestServer()")
public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
    long start = System.currentTimeMillis();
    ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
    HttpServletRequest request = attributes.getRequest();
    Object result = proceedingJoinPoint.proceed();
    RequestInfo requestInfo = new RequestInfo();
    requestInfo.setIp(request.getRemoteAddr());
    requestInfo.setUrl(request.getRequestURL().toString());
    requestInfo.setHttpMethod(request.getMethod());
    requestInfo.setClassMethod(String.format("%s.%s", proceedingJoinPoint.getSignature().getDeclaringTypeName(), proceedingJoinPoint.getSignature().getName()));
    requestInfo.setRequestParams(getRequestParamsByProceedingJoinPoint(proceedingJoinPoint));
    requestInfo.setResult(result);
    requestInfo.setTimeCost(System.currentTimeMillis() - start);
    LOGGER.info("Request Info      : {}", JSON.toJSONString(requestInfo));
    return result;
}

Serializing the RequestInfo object yields a clear, parsable log entry.

Logging Exceptions

@Data
public class RequestErrorInfo {
    private String ip;
    private String url;
    private String httpMethod;
    private String classMethod;
    private Object requestParams;
    private RuntimeException exception;
}

@AfterThrowing(pointcut = "requestServer()", throwing = "e")
public void doAfterThrow(JoinPoint joinPoint, RuntimeException e) {
    ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
    HttpServletRequest request = attributes.getRequest();
    RequestErrorInfo requestErrorInfo = new RequestErrorInfo();
    requestErrorInfo.setIp(request.getRemoteAddr());
    requestErrorInfo.setUrl(request.getRequestURL().toString());
    requestErrorInfo.setHttpMethod(request.getMethod());
    requestErrorInfo.setClassMethod(String.format("%s.%s", joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName()));
    requestErrorInfo.setRequestParams(getRequestParamsByJoinPoint(joinPoint));
    requestErrorInfo.setException(e);
    LOGGER.info("Error Request Info : {}", JSON.toJSONString(requestErrorInfo));
}

For exceptions, execution time is omitted; the log captures request details and the thrown exception.

Adding traceId for End‑to‑End Tracing

public class LogInterceptor implements HandlerInterceptor {
    private static final String TRACE_ID = "traceId";
    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        String traceId = java.util.UUID.randomUUID().toString().replaceAll("-", "").toUpperCase();
        ThreadContext.put("traceId", traceId);
        return true;
    }
    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        ThreadContext.remove(TRACE_ID);
    }
}

The interceptor injects a unique traceId into the logging context before each request and removes it afterward.

<property name="pattern">[TRACEID:%X{traceId}] %d{HH:mm:ss.SSS} %-5level %class{-1}.%M()/%L - %msg%xEx%n</property>

Updating the log pattern includes the traceId in every log line, simplifying traceability across services.