接口服務中的日志

先來看下日志對於一個接口服務的作用：

• 監控服務的狀態，一般程序中會增加一些跟蹤或者提示性的日志，用來判斷服務執行的詳細情況，特別是執行一些復合功能的接口或者叫聚合接口非常有利於我們判斷接口的執行情況
• 安全，用來分析調用者的身份信息，防止接口被非法惡意調用等
• 性能，可以統計每個接口的訪問執行時間來分析系統的瓶頸
• 異常分析，對於線上的異常，在沒有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完成，其它的復雜點的就是通過反射來完成參數以及值。記錄日志根據注解的配置來判斷應該記錄哪些日志項。

@Aspect
public 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

http://www.cnblogs.com/ASPNET2008/p/5813518.html