接口服务中的日志

 

先来看下日志对于一个接口服务的作用：

•  监控服务的状态，一般程序中会增加一些跟踪或者提示性的日志，用来判断服务执行的详细情况，特别是执行一些复合功能的接口或者叫聚合接口非常有利于我们判断接口的执行情况
•  安全，用来分析调用者的身份信息，防止接口被非法恶意调用等
•  性能，可以统计每个接口的访问执行时间来分析系统的瓶颈
•  异常分析，对于线上的异常，在没有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