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, enhanced code readability and maintainability

Therefore, when you want to print the request log, it is easy to think of the aspect and invade the control layer code 0

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() { }Copy the code

    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());
}
Copy the code

    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; }Copy the code

    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(); } requestParams.put(paramNames[I], value); } return requestParams; }Copy the code

      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========================");
}
Copy the code

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========================"); } @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(); } requestParams.put(paramNames[I], value); } return requestParams; }}Copy the code

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;
}
Copy the code

  • 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; }Copy the code

    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 concurrencyPrint abnormal request informationHandle methods that throw exceptions by 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;
}
Copy the code

  • 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));
}
Copy the code

    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

= = = = = = = = = = = = = = = = = = = = the following update in 2019/3/14 = = = = = = = = = = = = = = about tracking traceId hid in Kelvin comments 】 【, can according to the article traceId tracking the whole call chain, This section 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); }}Copy the code

    Add traceId through ThreadContext before invocation and remove traceId after invocation

  • Modify the log configuration file

Add placeholders for traceId [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?

= = = = = = = = = = = = = = = = = = = = the following update in 2019/3/16 = = = = = = = = = = = = = = log4j2 also can be used together with the MDC

/

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

= = = = = = = = = = = = = = = = = = = = the following update in 2021/6/15 = = = = = = = = = = = = = =

Enthusiastic netizen comment

If (Value instanceof MultipartFile)? But what if the argument hits List Files? That doesn’t seem to work that way

Where the code does lack consideration, the solution is as follows:

If (value instanceof List) {try {List<MultipartFile> multipartFiles = castList(value, MultipartFile.class); if (multipartFiles! = null) { List<String> fileNames = new ArrayList<>(); for (MultipartFile file : multipartFiles) { fileNames.add(file.getOriginalFilename()); } requestParams.put(paramNames[i], fileNames); break; }} catch (ClassCastException e) {// Ignore List that is not a file type}}Copy the code

Select * from castList (); select * from castList ();

public static <T> List<T> castList(Object obj, Class<T> clazz) { List<T> result = new ArrayList<T>(); if (obj instanceof List<? >) { for (Object o : (List<? >) obj) { result.add(clazz.cast(o)); } return result; } return null; }Copy the code

The complete code after modification is:

@Component @Aspect public class RequestLogAspect { private final static Logger LOGGER = LoggerFactory.getLogger(RequestLogAspect.class); @Pointcut("execution(* com.hikvision.trainplatform.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(); If (value instanceof List) {system.out.println ("Yes...") ); try { List<MultipartFile> multipartFiles = castList(value, MultipartFile.class); if (multipartFiles! = null) { List<String> fileNames = new ArrayList<>(); for (MultipartFile file : multipartFiles) { fileNames.add(file.getOriginalFilename()); } requestParams.put(paramNames[i], fileNames); break; }} Catch (ClassCastException e) {// Ignore List that is not a file type}} requestParams.put(paramNames[I], value); } return requestParams; } public static <T> List<T> castList(Object obj, Class<T> clazz) { List<T> result = new ArrayList<T>(); if (obj instanceof List<? >) { for (Object o : (List<? >) obj) { result.add(clazz.cast(o)); } return result; } return null; } @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