寫個日誌請求切面，先後端甩鍋更方便

時間  2020-03-21
標籤 日誌 請求 切面 後端 方便 简体版
原文   原文鏈接
最近項目進入聯調階段，服務層的接口須要和協議層進行交互，協議層須要將入參[json字符串]組裝成服務層所需的json字符串，組裝的過程當中很容易出錯。入參出錯致使接口調試失敗問題在聯調中出現不少次，所以就想寫一個請求日誌切面把入參信息打印一下，同時協議層調用服務層接口名稱對不上也出現了幾回，經過請求日誌切面就能夠知道上層是否有沒有發起調用，方便先後端甩鍋還能拿出證據

寫在前面

本篇文章是實戰性的，對於切面的原理不會講解，只會簡單介紹一下切面的知識點java

切面介紹

面向切面編程是一種編程範式，它做爲OOP面向對象編程的一種補充，用於處理系統中分佈於各個模塊的橫切關注點，好比事務管理、權限控制、緩存控制、日誌打印等等。
AOP把軟件的功能模塊分爲兩個部分：核心關注點和橫切關注點。業務處理的主要功能爲核心關注點，而非核心、須要拓展的功能爲橫切關注點。AOP的做用在於分離系統中的各類關注點，將核心關注點和橫切關注點進行分離，使用切面有如下好處：編程

  • 集中處理某一關注點/橫切邏輯
  • 能夠很方便的添加/刪除關注點
  • 侵入性少，加強代碼可讀性及可維護性

所以當想打印請求日誌時很容易想到切面，對控制層代碼0侵入json

切面的使用【基於註解】

  • @Aspect => 聲明該類爲一個註解類

切點註解：後端

  • @Pointcut => 定義一個切點，能夠簡化代碼

通知註解：緩存

  • @Before => 在切點以前執行代碼
  • @After => 在切點以後執行代碼
  • @AfterReturning => 切點返回內容後執行代碼，能夠對切點的返回值進行封裝
  • @AfterThrowing => 切點拋出異常後執行
  • @Around => 環繞，在切點先後執行代碼

動手寫一個請求日誌切面

  • 使用@Pointcut定義切點併發

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

    @Pointcut定義了一個切點，由於是請求日誌切邊，所以切點定義的是Controller包下的全部類下的方法。定義切點之後在通知註解中直接使用requestServer方法名就能夠了框架

  • 使用@Before再切點前執行dom

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

    在進入Controller方法前，打印出調用方IP、請求URL、HTTP請求類型、調用的方法名ide

  • 使用@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;
}

    打印了入參、結果以及耗時

    • getRquestParams方法

      private Map<String, Object> getRequestParams(ProceedingJoinPoint proceedingJoinPoint) {
     Map<String, Object> requestParams = new HashMap<>();

      //參數名
     String[] paramNames = ((MethodSignature)proceedingJoinPoint.getSignature()).getParameterNames();
     //參數值
     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;
 }
      經過 @PathVariable以及@RequestParam註解傳遞的參數沒法打印出參數名，所以須要手動拼接一下參數名，同時對文件對象進行了特殊處理，只需獲取文件名便可

  • @After方法調用後執行

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

沒有業務邏輯只是打印了End

  • 完整切面代碼

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

        //參數名
        String[] paramNames = 
((MethodSignature)proceedingJoinPoint.getSignature()).getParameterNames();
        //參數值
        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;
    }
}
```

高併發下請求日誌切面

寫完之後對本身的代碼很滿意，可是想着可能還有完善的地方就和朋友交流了一下。emmmm

果真還有繼續優化的地方
每一個信息都打印一行，在高併發請求下確實會出現請求之間打印日誌串行的問題，由於測試階段請求數量較少沒有出現串行的狀況，果真生產環境纔是第一發展力，可以遇到更多bug，寫更健壯的代碼
解決日誌串行的問題只要將多行打印信息合併爲一行就能夠了，所以構造一個對象

  • 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;
}

  • 環繞通知方法體

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

    將url、http request這些信息組裝成RequestInfo對象，再序列化打印對象<br/> 打印序列化對象結果而不是直接打印對象是由於序列化有更直觀、更清晰，同時能夠藉助在線解析工具對結果進行解析


是否是還不錯
在解決高併發下請求串行問題的同時添加了對異常請求信息的打印，經過使用 @AfterThrowing註解對拋出異常的方法進行處理

  • RequestErrorInfo.java

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

    對於異常，耗時是沒有意義的，所以不統計耗時，而是添加了異常的打印

最後放一下完整日誌請求切面代碼：

@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) {
        //參數名
        String[] paramNames = ((MethodSignature)proceedingJoinPoint.getSignature()).getParameterNames();
        //參數值
        Object[] paramValues = proceedingJoinPoint.getArgs();

        return buildRequestParam(paramNames, paramValues);
    }

    private Map<String, Object> getRequestParamsByJoinPoint(JoinPoint joinPoint) {
        //參數名
        String[] paramNames = ((MethodSignature)joinPoint.getSignature()).getParameterNames();
        //參數值
        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;
    }
}

趕忙給大家的應用加上吧【若是沒加的話】，沒有日誌的話，總懷疑上層出錯，可是卻拿不出證據

==================== 如下內容更新於2019/3/14 ==============

關於traceId 跟蹤定位【地藏Kelvin的評論】，能夠根據traceId跟蹤整條調用鏈，以log4j2爲例介紹如何加入traceId

  • 添加攔截器

    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);
    }
}

    在調用前經過ThreadContext加入traceId，調用完成後移除

  • 修改日誌配置文件

在原來的日誌格式中
添加traceId的佔位符

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

    日誌跟蹤更方便

DMC是配置logback和log4j使用的，使用方式和ThreadContext差很少，將ThreadContext.put替換爲MDC.put便可，同時修改日誌配置文件。
推薦使用log4j2，爲何推薦使用log4j2能夠看下這篇文章：日誌框架，選擇Logback Or Log4j2？

==================== 如下內容更新於2019/3/16 ==============

log4j2也是能夠配合MDC一塊兒使用的

MDC是slf4j包下的，其具體使用哪一個日誌框架與咱們的依賴有關

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程