介面服務中的日誌，介面服務日誌

介面服務中的日誌，介面服務日誌

 

先來看下日誌對於一個介面服務的作用：

•  監控服務的狀態，一般程式中會增加一些跟蹤或者提示性的日誌，用來判斷服務執行的詳細情況，特別是執行一些複合功能的介面或者叫彙總介面非常有利於我們判斷介面的執行情況
•  安全，用來分析調用者的身份資訊，防止介面被非法惡意調用等
•  效能，可以統計每個介面的訪問執行時間來分析系統的瓶頸
•  異常分析，對於線上的異常，在沒有debug的環境下，要想分析問題原因最有價值的就要算異常的堆棧資訊

上面的這幾點需求，如果介面服務使用的是一些進階產品比如dubbo，其實它已經實現了大部分功能，不需要人為的去全部處理功能。

•   安全，可利用訪問日誌的功能來實現，訪問日誌中詳細的記錄了用戶端調用的時間，身份，調用時的詳細參數。  

[DUBBO] [2016-08-27 14:47:06] 10.10.50.20:64948 -> 10.10.50.20:20960 - ProductFacadeService getDataDictionaryByType(DataDictionaryParamInfo) [{"code":0,"type":1}], dubbo version: 2.8.1, current host: 10.10.50.20

        上面的日誌我們可以看到如下有用的資訊：

         1：調用方IP以及連接埠資訊：10.10.50.20:64948

         2：服務端的IP以及連接埠資訊：10.10.50.20:20960

         3：調用時間：2016-08-27 14:47:06

         4：調用的介面方法：ProductFacadeService getDataDictionaryByType(DataDictionaryParamInfo)
         5：調用的介面方法參數：[{"code":0,"type":1}]

•   異常分析，會自動將產生的未捕獲異常資訊記錄到日誌中，不需要手工的去處理異常的記錄。上面訪問日誌中的參數記錄資訊也對分析線上問題提供了非常有力的協助。

其實dubbo自己提供的日誌功能已經非常強了，大多數情況下已經夠用，但如果想有一些更加強的功能就需要自己想想辦法了：

•   監控服務的狀態，這類跟蹤資訊只能依靠程式邏輯來實現，沒有其它捷徑
•   效能，dubbo的訪問日誌只記錄了介面調用的開始時間，沒有結束時間，要想統計某個方法或者某個請求的整體執行時間是無能為力的

如果你的服務介面不是dubbo，比如是基於spring mvc 實現的rest api介面，那麼就沒有上面dubbo幫你做的那些好用的日誌功能了。但是spring mvc實現上面的日誌需求方法也是很多的，典型的例子可以藉助HandlerInterceptor這類攔截器，只需要實現這個介面,然後在實作類別中增加日誌功能即可：我們可以通過handler這個參數來擷取你想要的所有資料，另外還有request以及response兩個資訊豐富的對象供你使用。

public interface HandlerInterceptor {    boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler)        throws Exception;    void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView)            throws Exception;        void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex)            throws Exception;}

 

還有一種是自己實現一個AOP功能去解決我們的需求問題。AOP不是這篇的重點，我貼一張圖用來簡單展示AOP的作用（上面提到的HandlerInterceptor 也屬於AOP的具體應用）。

將某些非業務的功能通過攔截的形式注入到流程中，而非緊密耦合在商務邏輯中，比如下面的記錄方法參數的代碼就是緊耦合，不推薦：

public ValueResult<ApplyIsvRoleInfo> queryUserApplyIsvInfo(String appKey, String accessToken) {        log.info("receive queryUserApplyIsvInfo! and the params appKey: [" + appKey + "], accessToken:[" + accessToken + "]");     ...... do something}

AOP我這裡使用aspectj，當然也可以使用spring內建的。

•   建立一個用於日誌的註解，用來控制記錄的具體功能。比如有些方法是不推薦記錄返回記錄的，像列表查詢，也有利於精確的配置日誌生效的範圍

 @Target({ElementType.METHOD})@Retention(RetentionPolicy.RUNTIME)public @interface MethodLog {    /**     * 是否開機記錄功能     * @return     */    boolean enable() default true;    /**     * 是否記錄傳回值     * 列表資料不推薦記錄     * @return     */    boolean isLogResult() default false;    /**     * 是否記錄方法的參數名稱以及值     * @return     */    boolean isLogParameter() default true;    /**     * 是否記錄執行時間     * @return     */    boolean isLogElapsed() default true;}

• 建立一個服務端的日誌攔截器，由於我們需要記錄方法的執行時間，那麼最適合的就是寫一個around的方法，在方法執行前後記錄時間從而計算出時間差。對於參數，我們也很容易實現，根據反射我們可以輕鬆得到調用方法的所有參數名稱以及參數的具體值，下面是實現這個攔截器用的工具類介紹：

         a:計算時間，這裡採用google提供的Stopwatch，這個東西對於從.NET轉JAVA的來講太親切了

       Stopwatch sw=Stopwatch.createStarted();        Object result = joinPoint.proceed();        sw.stop();        long elapsed=sw.elapsed(TimeUnit.NANOSECONDS);

    
        b:記錄參數內容，對於object對象，我們將其序列化成json，可以利用jackson完成，其它的複雜點的就是通過反射來完成參數以及值。記錄日誌根據註解的配置來判斷應該記錄哪些日誌項。

@Aspectpublic class ServicesLoggerInterceptor {    @Pointcut("execution(* com.chanjet.csp.product.service.service.impl.*ServiceImpl*.*(..))")    public void pointCut() {    }    @Around(value = "pointCut()")    public Object around(ProceedingJoinPoint joinPoint) throws Throwable {        Stopwatch sw=Stopwatch.createStarted();        Object result = joinPoint.proceed();        sw.stop();        long elapsed=sw.elapsed(TimeUnit.NANOSECONDS);        MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature();        Method targetMethod = methodSignature.getMethod();        MethodLog methodLog= targetMethod.getAnnotation(MethodLog.class);        if(null!=methodLog&&methodLog.enable()){            StringBuilder logLine = new StringBuilder(joinPoint.getSignature().getName());            if(methodLog.isLogParameter()) {                Object[] paramValues = joinPoint.getArgs();                CodeSignature codeSignature= ((CodeSignature) joinPoint.getSignature());                String[] paramNames = codeSignature.getParameterNames();                logLine.append("(");                if (paramNames.length != 0) {                    AspectLogUtils.logParamValues(logLine, paramNames, paramValues);                }                logLine.append(") - started");            }            if(methodLog.isLogResult()) {                logLine.append("  Return Value : ");                logLine.append(AspectLogUtils.toString(result));            }            if(methodLog.isLogElapsed()) {                logLine.append("  elapsed nanoseconds:" + elapsed);            }            AspectLogUtils.getLogger().info(logLine.toString());        }        return result;    }}

       c:建立一個日誌的工具類，用來實現具體的日誌記錄。

public final  class AspectLogUtils {    private static Logger logger = LoggerFactory.getLogger(AspectLogUtils.class);    private AspectLogUtils() {    }    public static Logger getLogger() {        return logger;    }    public static void logParamValues(StringBuilder logLine, String[] paramNames, Object[] paramValues) {        for (int i = 0; i < paramValues.length; i++) {            logLine.append(paramNames[i]).append("=").append(toString(paramValues[i]));            if (i < paramValues.length - 1) {                logLine.append(", ");            }        }    }    public static String toString(Object object) {        return JsonUtils.toJsonString(object);    }}

• 在Spring中載入這個攔截器

<bean class="ServicesLoggerInterceptor"></bean>    <aop:aspectj-autoproxy proxy-target-class="true"/>

INFO  getDataDictionaryByType(dataDictionaryParamInfo={"type":1,"code":0}) - started  elapsed nanoseconds:11491670