Interface service logs

Interface service logs

First, let's take a look at the effect of logs on an interface service:

• Monitors the status of the service. Generally, some tracing or prompt logs are added to the program to determine the details of service execution, in particular, the interfaces or aggregate interfaces that execute some compound functions are very helpful for us to judge the execution of interfaces.
• Security: used to analyze the identity information of the caller and prevent the interface from being illegally and maliciously called.
• Performance. You can calculate the access execution time of each interface to analyze the system bottleneck.
• Exception analysis: for online exceptions, in environments without debugging, the most valuable reason for the problem is to calculate the stack information of the exception.

In the above requirements, if the interface service uses some advanced products such as dubbo, it has actually implemented most of the functions and does not need to be processed completely.

• Security: You can use the access log function. The access log details the time, identity, and detailed parameters of the client call.

[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

The above log shows the following useful information:

1: caller IP address and port information: 10.10.50.20: 64948

2: Server IP address and port information: 10.10.50.20: 20960

3: Call time: 14:47:06

4: The called interface method is ProductFacadeService getDataDictionaryByType (DataDictionaryParamInfo)
5: interface method parameter called: [{"code": 0, "type": 1}]

• Exception analysis automatically records the uncaptured exception information in the log, and does not need to be processed manually. The parameter record information in the above access log is also very helpful for analyzing online problems.

In fact, dubbo's own log function is already very powerful, and it is enough in most cases, but if you want to have some more enhanced functions, you need to think about it yourself:

• Monitors the status of the service. This type of tracking information can only be achieved through program logic, and there is no other shortcut
• Performance: dubbo access logs only record the interface call start time, there is no end time, to count the overall execution time of a method or a request is powerless

If your service interface is not dubbo, for example, a rest api interface based on spring mvc, there will be no good log functions that dubbo can help you. However, spring mvc also provides many methods to implement the preceding log requirements. For a typical example, you can use HandlerInterceptor to implement this interface and then add the log function to the implementation class: we can use the handler parameter to obtain all the data you want. In addition, there are two rich objects, request and response, for your use.

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

 

Another way is to implement an AOP function to solve our needs. AOP is not the focus of this article. I will post a figure to briefly demonstrate the role of AOP (the HandlerInterceptor mentioned above also belongs to the specific application of AOP ).

Some non-business functions are injected into the process through interception, rather than tightly coupled in the business logic. For example, the code of the record method parameters below is tightly coupled and is not recommended:

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

I use aspectj here. Of course, you can also use the built-in spring.

• Create a log annotation to control the logging function. For example, some methods do not recommend record returned records, such as list queries, but also help to precisely configure the log effective range.

@ Target ({ElementType. METHOD}) @ Retention (RetentionPolicy. RUNTIME) public @ interface MethodLog {/*** whether to enable the log function * @ return */boolean enable () default true; /* ** whether to record the returned value * List data is not recommended record * @ return */boolean isLogResult () default false; /*** whether to record the parameter name and value of the Method * @ return */boolean isLogParameter () default true; /*** whether to record the execution time * @ return */boolean isLogElapsed () default true ;}

• Create a log interceptor for the server. Because we need to record the execution time of the method, the most suitable method is to write an around method, and record the time before and after the method execution to calculate the time difference. We can also easily implement parameters. Based on reflection, we can easily get all the parameter names and specific values of the called method. The following is a tool class for implementing this Interceptor:

A: computing time. Here we use Stopwatch provided by google. This is so friendly for switching from. NET to JAVA.

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

B: record the parameter content. For object objects, we serialize them into json, which can be completed by jackson. Other complex points are parameters and values through reflection. Record logs determine which log entries should be recorded based on the annotation configuration.

@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: Create a logging tool class to implement specific logging.

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

• Load this interceptor in Spring

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

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