Recently, the project entered the joint commissioning stage. The interface of the service layer needs to interact with the protocol layer, and the protocol layer needs to assemble the input parameter [JSON string] into the JSON string required by the service layer. It is easy to make mistakes during the assembly process.

Into and cause the failure of interface debugging problems in alignment error in many times, so they want to write a request log section put into the information a print, at the same time, the protocol layer to invoke the service layer interface name also appeared in several times, by requesting the log section can know whether the upper have initiated calls, convenient pot can also take out the evidence before and after the end.

Writing in the front

This article is practical, for the principle of cutting surface will not explain, will simply introduce the knowledge of cutting surface

Section introduces

Section-oriented programming is a programming paradigm that complements OOP object-oriented programming to address cross-cutting concerns that are distributed across modules in a system, such as transaction management, permission control, cache control, log printing, and so on.

AOP divides the functional modules of software into two parts: core concerns and crosscutting concerns. The main function of the business process is the core concern, and the non-core function that needs to be extended is the crosscutting concern. AOP’s role is to separate the various concerns in a system, separating core concerns from crosscutting concerns, and using aspects has the following benefits:

  • Focus on one concern/crosscutting logic

  • You can easily add/remove concerns

  • Less intrusive, enhance code readability and maintainability, so when you want to print the request log it is easy to think of the cut side, the control layer code 0 intrusion

Use of sections [Based on notes]

  • @aspect => declare this class as an annotation class

Pointcut notes:

  • @pointcut => Define a Pointcut to simplify code

Notice notes:

  • @before => Execute code Before pointcut

  • @after => Execute the code After the pointcut

  • The return value of the pointcut can be encapsulated by executing the code after the pointcut returns

  • AfterThrowing => Execute after pointcut throws an exception

  • @around => wrap Around, execute code before and after the pointcut

Start writing a request log section

  • Use @pointcut to define pointcuts

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

Pointcut defines a Pointcut that, since it is a request log cut, defines methods under all classes in the Controller package. After defining the pointcut, use the requestServer method name directly in the notification annotation

  • Use @before to execute Before the pointcut

    @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());

    }

Before entering the Controller method, print out the caller’S IP, request URL, HTTP request type, and method name called

  • Use @around to print an entry parameter into the control layer

    @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;

    }

Input parameters, results, and elapsed time are printed

  • GetRquestParams method

    private Map<String, Object> getRequestParams(ProceedingJoinPoint proceedingJoinPoint) {

    Map<String, Object> requestParams = new HashMap<>();

    / / parameter name String [] paramNames = (.) (MethodSignature proceedingJoinPoint getSignature ()). GetParameterNames (); / / parameter value Object [] paramValues = proceedingJoinPoint. GetArgs ();

    for (int i = 0; i < paramNames.length; i++) {

    Object value = paramValues[i];

    If (value instanceof MultipartFile) {MultipartFile file = (MultipartFile) value; value = file.getOriginalFilename(); // get the file name}

    requestParams.put(paramNames[i], value);

    }

    return requestParams;

    }

Parameters passed with @pathVariable and @requestParam annotations cannot be printed with parameter names, so you need to manually concatenate the parameter names and do special processing for the file object, just get the file name

  • Execute After the @after method is called

    @After(“requestServer()”)

    public void doAfter(JoinPoint joinPoint) {

    LOGGER.info(“===============================End========================”);

    }

No business logic just prints End

  • Complete section code

    @Component

    @Aspect

    public class RequestLogAspect {

    private final static Logger LOGGER = LoggerFactory.getLogger(RequestLogAspect.class);

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

    @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());

    }

    @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;

    }

    @After(“requestServer()”)

    public void doAfter(JoinPoint joinPoint) {

    LOGGER.info(“===============================End========================”);

    }

    / * *

    • Get into arguments
    • @param proceedingJoinPoint
    • @return
    • * /

    private Map<String, Object> getRequestParams(ProceedingJoinPoint proceedingJoinPoint) {

    Map<String, Object> requestParams = new HashMap<>();

    / / parameter name String [] paramNames = (.) (MethodSignature proceedingJoinPoint getSignature ()). GetParameterNames (); / / parameter value Object [] paramValues = proceedingJoinPoint. GetArgs ();

    for (int i = 0; i < paramNames.length; i++) {

    Object value = paramValues[i];

    If (value instanceof MultipartFile) {MultipartFile file = (MultipartFile) value; value = file.getOriginalFilename(); // get the file name}

    requestParams.put(paramNames[i], value);

    }

    return requestParams; }}

High concurrency request log facets

After writing the code, I was satisfied with it, but I talked to my friends about it because I thought there might be some improvements. emmmm

​

Sure enough, there are still places to continue to optimize each information to print a line, in high concurrency requests will indeed appear between requests to print the log serial problem, because the number of requests in the test phase is small, there is no serial situation, sure enough, the production environment is the first development force, can encounter more bugs, Write more robust code to solve the log serialization problem by combining multiple lines of print information into one line, so construct an object

  • RequestInfo.java

    @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;

    }

  • Wrap around the notification method body

    @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;

    }

The reason for serializing the results of a serialized object is that serialization is more intuitive and clear, and the results can be parsed using online parsing tools

​

Isn’t that good?

A pair is added while addressing the serialization of requests under high concurrency

The printing of exception request information, handled by the method that threw the exception using the @Afterthrowing annotation

  • RequestErrorInfo.java

    @Data

    public class RequestErrorInfo {

    private String ip;

    private String url;

    private String httpMethod;

    private String classMethod;

    private Object requestParams;

    private RuntimeException exception;

    }

  • Exception notification surround

    @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, the elapsed time is meaningless, so the elapsed time is not counted and the printing of the exception is added

Finally, here is the complete log request section code:

@Component @Aspect public class RequestLogAspect { private final static Logger LOGGER = LoggerFactory.getLogger(RequestLogAspect.class); @Pointcut("execution(* your_package.controller.. * (..) )") public void requestServer() { } @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; } @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)); } @param proceedingJoinPoint ** @return ** / private Map<String, Object > getRequestParamsByProceedingJoinPoint (ProceedingJoinPoint ProceedingJoinPoint) {/ / parameter name String [] paramNames = ((MethodSignature)proceedingJoinPoint.getSignature()).getParameterNames(); / / parameter value Object [] paramValues = proceedingJoinPoint. GetArgs (); return buildRequestParam(paramNames, paramValues); } private Map<String, The Object > getRequestParamsByJoinPoint (JoinPoint JoinPoint) {/ / parameter name String [] paramNames = ((MethodSignature)joinPoint.getSignature()).getParameterNames(); // Parameter Values Object[] paramValues = joinPoint.getargs (); return buildRequestParam(paramNames, paramValues); } private Map<String, Object> buildRequestParam(String[] paramNames, Object[] paramValues) { Map<String, Object> requestParams = new HashMap<>(); for (int i = 0; i < paramNames.length; i++) { Object value = paramValues[i]; If (value instanceof MultipartFile) {MultipartFile file = (MultipartFile) value; value = file.getOriginalFilename(); } requestParams.put(paramNames[I], value); } return requestParams; } @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; } @Data public class RequestErrorInfo { private String ip; private String url; private String httpMethod; private String classMethod; private Object requestParams; private RuntimeException exception; }}Copy the code

Add it to your application quickly [if not], if there is no log, always suspect that the upper level is wrong, but there is no evidence

​

You can trace the entire invocation chain based on traceId. The following uses log4j2 as an example to describe how to add traceId

  • Adding interceptors

    public class LogInterceptor implements HandlerInterceptor {

    private final static 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 postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView)

    throws Exception {

    }

    @Override public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception { ThreadContext. remove(TRACE_ID); }}

Add traceId through ThreadContext before invocation and remove traceId after invocation

  • Modify the log configuration file. Add the traceId placeholders to the original log format

    [TRACEID:%X{traceId}] %d{HH:mm:ss.SSS} %-5level %class{-1}.%M()/%L – %msg%xEx%n

  • perform

​

Log tracing is more convenient

DMC is used to configure logback and log4j in much the same way as ThreadContext. Replace threadContext. put with mdC.put and modify the log configuration file.

Log4j2 is recommended. Why log4j2 is recommended?

Log4j2 can also work with MDC

​

MDC is under the SLF4J package, and which logging framework it uses depends on our dependencies