日志记录全流程

日志

这个博文记录一下我在一个实际项目开发过程中的日志记录节点和信息。

不一定是最完美的，但是算是自己的一次尝试。

以后如果有更好的方案再改进。

先说下背景。进入公司半年后，我自己负责了一个系统的后端开发工作。通过这个工作，算是把公司整个项目的开发流程整明白了。这个开发流程包括从项目开始立项的需求讨论、需求分析，到系统设计、详细设计，再到数据结构设计、接口设计、前后端分工，最后完成开发工作。我的主要工作是系统设计和后端开发，通过这次的开发任务，对系统设计算是入个小小的门，对后端开发也有了新的认识。其中，最大的认识就是如何做日志记录以及稳定性建设的工作。

稳定性建设是我之前从来没有接触过的东西，我这次做的也并不是很完善，有很多需要改进的地方。这篇文章里就不说了。

主要还是说一下日志记录的全流程。

之前接触过的系统日志记录都相对比较简陋，而且有很多代码冗余和难以维护的点。比如，为了记录接口的参数和返回值，直接把log.info/debug写入到方法里。这样的方式导致的结果就是每次新增方法都需要重新写这部分日志记录代码，在业务代码中就会有很多这样日志记录代码。还有一个点是，为了能在日志中体现日志所在的方法，就必须在打印日志时把方法名称带上。

为了更好的记录日志，我把日志记录分为了几个层次。从后端分层来看，分为了controller层和service层。从接口的类型来看，分为了API接口和web接口。针对不同的分类，日志的记录也是不同的。

0x01 后端分层日志记录

controller层和service层最大的不同就是，controller层的外层可以使用拦截器，而service层不行。也就是说controller层的日志记录可以放在拦截器里进行。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
/**
 * 系统trace日志记录
 * @author chenghao
 * @create 2020-05-13 11:10
 */
public class TraceLogInterceptor extends HandlerInterceptorAdapter {
    Logger logger = LoggerFactory.getLogger(TRACE_LOG);

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        // 设置请求开始时间
        String traceId = request.getHeader(TraceConsts.DIDI_HEADER_RID);
        if (StringUtils.isBlank(traceId)) {
            logger.warn("method:traceLog not found traceId");
            traceId = SpanIdGenerator.getTraceId();
        }
        MDC.put(TraceConsts.TRACEID, traceId); //公司日志记录工具类
        LogMessage.setTraceId(traceId); //公司日志记录工具类

        //上游的传递的spanid
        String spanId = request.getHeader(TraceConsts.DIDI_HEADER_SPANID);
        if (StringUtils.isBlank(spanId)) {
            spanId = SpanIdGenerator.getSpanId();
        }
        MDC.put(TraceConsts.SPANID, spanId);
        LogMessage.setSpanId(spanId);

        String hintCode = request.getHeader(TraceConsts.DIDI_HEADER_HINT_CODE);
        if (StringUtils.isBlank(hintCode)) {
            hintCode = "0";
        }
        Long hc = 0L;
        try {
            hc = Long.parseLong(hintCode);
        } catch (Exception e) {
        }
        MDC.put(TraceConsts.HINT_CODE, hc.toString());
        LogMessage.setHintCode(hc);

        String hintContent = request.getHeader(TraceConsts.DIDI_HEADER_HINT_CONTENT);
        if (StringUtils.isBlank(hintContent)) {
            hintContent = "";
        }
        MDC.put(TraceConsts.HINT_CONTENT, hintContent);
        LogMessage.setHintContent(hintContent);

        request.setAttribute("startTime", System.currentTimeMillis());

        LogMessage logMessage = new LogMessage();
        logMessage.setDltag(DltagConsts._COM_REQUEST_IN);
        logMessage.add(TraceConsts.URI, request.getRequestURI());

        // 如果接口是上传文件，则忽略该参数
        if (StringUtils.isNotBlank(request.getContentType())
                && request.getContentType().startsWith(ContentType.MULTIPART_FORM_DATA.getMimeType())) {
            logMessage.add("args", "");
        } else {
            if (POST.name().equals(request.getMethod())) {
                BufferedReader reader = request.getReader();
                String line = "";
                StringBuilder args = new StringBuilder();
                while ((line = reader.readLine()) != null) {
                    args.append(line.trim());
                }
                logMessage.add("args", args.toString());
            } else {
                logMessage.add("args", JSON.toJSONString(request.getParameterMap()));
            }
        }
        logger.info(logMessage.toString());
        return true;
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        LogMessage logMessage = new LogMessage();
        logMessage.setDltag(DltagConsts._COM_REQUEST_OUT);
        logMessage.add(TraceConsts.URI, request.getRequestURI());
        long startTime = (Long)request.getAttribute("startTime");
        logMessage.add(TraceConsts.PROC_TIME, (System.currentTimeMillis() - startTime)/1000.0);
        if (ex != null) {
            logMessage.add(TraceConsts.ERRNO, 500);
            if (ex.getCause() != null) {
                logMessage.add(TraceConsts.ERRMSG, ex.getCause().getMessage());
            }
        } else {
            logMessage.add(TraceConsts.ERRNO, 200);
            logMessage.add(TraceConsts.ERRMSG, "success");
        }
        // 排除掉后台运维接口的日志
        if (!request.getRequestURI().startsWith("/admin")) {
            byte[] body = new byte[0];
            if (response instanceof ContentCachingResponseWrapper) {
                body = ((ContentCachingResponseWrapper) response).getContentAsByteArray();
            }
            logMessage.add("result", new String(body));
        }
        logger.info(logMessage.toString());
        MDC.clear();
    }
}

通过拦截器我们可以很方便的记录每个controller方法的参数和返回值。在这里我们不仅仅记录了方法的参数是什么，返回是什么，还记录请求uri、请求响应时间、traceId、spanid、cspanid。后面三个值是为了进行全链路日志查询。关于traceId在这里就不多说了。

但是service层没有拦截器应该怎么办？首先，我们应该知道的是拦截器的原理是使用面向切面的编程在controller的外层加了一层处理逻辑。那么，我们也可以参照这个思路在service层外也加一层日志记录的代码逻辑。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
/**
 * SOC全局日志记录
 * @author chenghao
 * @create 2020-05-12 17:56
 */
@Aspect
@Component
public class LogAspect {
    private Log log;

    public LogAspect() {
    }

    @Pointcut("@annotation(com.didichuxing.soc.common.annotation.LogAnnotation)")
    public void annotationPointCut(){}

    @Before("annotationPointCut()&&@annotation(logAnnotation)")
    public void before(JoinPoint joinPoint, LogAnnotation logAnnotation){
        log = LogFactory.getLog(logAnnotation.loggerName());
        LogMessage logMessage = new LogMessage();
        logMessage.setDltag("_com_method_in");
        logMessage.add("method", getClassAndMethodName(joinPoint));

        if (joinPoint.getArgs() != null) {
            Object[] args = joinPoint.getArgs().clone();
            // 隐去登录用户的隐私数据，只保留ID、邮箱、账号
            for (int i = 0; i < args.length; i++) {
                Object arg = args[i];
                if (arg instanceof LoginUser) {
                    Object copyArg = null;
                    try {
                        copyArg = ((LoginUser) arg).clone();
                        ((LoginUser) copyArg).setPhone(null);
                        ((LoginUser) copyArg).setPicture(null);
                        ((LoginUser) copyArg).setRealname(null);
                        ((LoginUser) copyArg).setTicket(null);
                        ((LoginUser) copyArg).setUserno(null);
                        ((LoginUser) copyArg).setRoles(null);
                    } catch (CloneNotSupportedException e) {
                        log.error("method:LogAspect.before ret: clone not Supported.", e);
                    }
                    args[i] = copyArg;
                }
                // 如果参数为文件，则排除
                if (arg instanceof MultipartFile) {
                    args[i] = null;
                }
            }
            String argsStr = JSON.toJSONString(args);
            logMessage.add("args", argsStr);
        } else {
            logMessage.add("args", null);
        }
        //获取参数列表
        log.info(logMessage.toString());
    }

    @AfterReturning(value = "annotationPointCut()&&@annotation(logAnnotation)",returning = "result")
    public void afterReturn(JoinPoint joinPoint, Object result, LogAnnotation logAnnotation){
        log = LogFactory.getLog(logAnnotation.loggerName());
        LogMessage logMessage = new LogMessage();
        logMessage.setDltag("_com_method_out");
        logMessage.add("method", getClassAndMethodName(joinPoint));
        //获取返回值
        String resultString = JSON.toJSONString(result);
        logMessage.add("result", resultString);
        logMessage.add(TraceConsts.ERRNO, 0);
        logMessage.add(TraceConsts.ERRMSG, "success");
        log.info(logMessage.toString());
    }

    @AfterThrowing(value = "annotationPointCut()&&@annotation(logAnnotation)",throwing = "ex")
    public void afterThrowing(JoinPoint joinPoint, Exception ex, LogAnnotation logAnnotation){
        log = LogFactory.getLog(logAnnotation.loggerName());
        LogMessage logMessage = new LogMessage();
        logMessage.setDltag("_com_method_fail");
        logMessage.add("method", getClassAndMethodName(joinPoint));
        logMessage.add(TraceConsts.ERRNO, 1);
        String msg = ex.getCause() == null ? ex.getMessage() : ex.getCause().getMessage();
        logMessage.add(TraceConsts.ERRMSG, msg);
        log.error(logMessage.toString());
    }

    /**
     * 根据切入点获取类名和方法名
     * @param joinPoint 切入点
     * @return ${className}-${methodName}
     */
    private String getClassAndMethodName(JoinPoint joinPoint) {
        String className = joinPoint.getSignature().getDeclaringTypeName();
        String methodName = joinPoint.getSignature().getName();
        return className + "." + methodName;
    }
}

在service层的日志记录和controller层大体相同，唯一不同的地方就是增加了调用方法的信息记录。

这样的日志记录可以覆盖到所有的请求方法的参数和返回值，方便于问题的排查。当然这仅仅是对方法的参数的返回值的记录，还有一个比较重要的日志记录是方法内的异常情况日志记录。比如，如果方法参数不符合要求，我们可以使用warn级别的日志进行记录，而异常情况的发生使用error级别进行记录。这样只要系统发生了异常情况，我们就可以从请求的参数、返回值、异常发生的上下文信息进行问题定位。为了更符合我们现在的日志记录，我在log4j的日志方法外又封装了一层。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
/**
 * Soc平台报错、告警日志记录接口
 * @author chenghao
 * @create 2020-05-14 11:41
 */
public abstract class SocLog {
    Log logger;

    public void setLogger(Log logger) {
        this.logger = logger;
    }

    /**
     * 记录方法执行过程中的错误日志
     * @param message 错误原因
     */
    public abstract void error(String message);

    /**
     * 记录方法执行过程中的错误日志
     * @param message 错误原因
     * @param e 报错信息参数
     */
    public abstract void error(String message, Throwable e);

    /**
     * 记录方法执行过程中的告警日志
     * @param message 告警原因
     */
    public abstract void warn(String message);
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
@Component(value = "socLog")
@Scope("prototype")
public class TraceLog extends SocLog {
    HttpRequestAdapter httpRequestAdapter;

    @Resource(name = "saMonitorRobotRequestHandler")
    HttpRequestHandler httpRequestHandler;

    @Resource
    private ThreadPoolTaskExecutor targetExecutor;

    public TraceLog() {
        this.httpRequestAdapter = new HttpRequestAdapter(new SaMonitorRobotRequestHandler());
    }

    @Override
    public void error(String message) {
        if (logger == null) {
            return;
        }
        LogMessage logMessage = new LogMessage();
        logMessage.setDltag("_com_method_error");

        // 获取当前方法调用者信息
        StackTraceElement[] arr = Thread.currentThread().getStackTrace();
        StringBuilder stringBuilder = new StringBuilder(100);
        stringBuilder.append(arr[2].getClassName())
                .append('(')
                .append(arr[2].getMethodName())
                .append(':')
                .append(arr[2].getLineNumber())
                .append(')');
        String method = stringBuilder.toString();
        logMessage.add("method", method);
        logMessage.add("message", message);
        logger.error(logMessage.toString());

        PropertiesUtil propertiesUtil = PropertiesUtil.load("config.properties");
        String env = propertiesUtil.getProValue("soc.deploy.env");
        String envName = "线上环境";
        if("dev".equals(env)){
            envName = "测试环境";
        }
        String text = "**环境类型：** " + envName + "\n\n"
                + "**请求方法：** " + method + "\n\n"
                + "**traceId：** " + logMessage.getTraceId() + "\n\n"
                + "**spanId：** " + logMessage.getSpanId() + "\n\n"
                + "**cspanId：** " + logMessage.getCspanId() + "\n\n"
                + "**报错信息：** " + message;
        final Map<String, String> content = new HashMap<>();
        content.put("text", text);
        targetExecutor.execute(new Runnable() {
            @Override
            public void run() {
                try {
                    httpRequestAdapter.handle(null, null, content);
                } catch (BaseException e) {
                    logger.error("send sa monitor message error.", e);
                }
            }
        });
    }

    @Override
    public void error(String message, Throwable e) {
        if (logger == null) {
            return;
        }
        LogMessage logMessage = new LogMessage();
        logMessage.setDltag("_com_method_error");

        // 获取当前方法调用者信息
        StackTraceElement[] arr = Thread.currentThread().getStackTrace();
        StringBuilder stringBuilder = new StringBuilder(100);
        stringBuilder.append(arr[2].getClassName())
                .append('(')
                .append(arr[2].getMethodName())
                .append(':')
                .append(arr[2].getLineNumber())
                .append(')');
        String method = stringBuilder.toString();
        logMessage.add("method", method);
        logMessage.add("message", message);
        logMessage.add("exception", getExceptionMessage(e));
        logger.error(logMessage.toString());

        PropertiesUtil propertiesUtil = PropertiesUtil.load("config.properties");
        String env = propertiesUtil.getProValue("soc.deploy.env");
        String envName = "线上环境";
        if("dev".equals(env)){
            envName = "测试环境";
        }
        String text = "**环境类型：** " + envName + "\n\n"
                + "**请求方法：** " + method + "\n\n"
                + "**traceId：** " + logMessage.getTraceId() + "\n\n"
                + "**spanId：** " + logMessage.getSpanId() + "\n\n"
                + "**cspanId：** " + logMessage.getCspanId() + "\n\n"
                + "**报错信息：** " + message + "\n\n"
                + "**异常信息：** \n\n"
                + "```\n\n"
                + getExceptionMessage(e) + "\n\n"
                + "```\n\n";
        final Map<String, String> content = new HashMap<>();
        content.put("text", text);
        targetExecutor.execute(new Runnable() {
            @Override
            public void run() {
                try {
                    httpRequestAdapter.handle(null, null, content);
                } catch (BaseException e) {
                    logger.error("send sa monitor message error.", e);
                }
            }
        });
    }

    @Override
    public void warn(String message) {
        if (logger == null) {
            return;
        }
        LogMessage logMessage = new LogMessage();
        logMessage.setDltag("_com_method_warn");

        // 获取当前方法调用者信息
        StackTraceElement[] arr = Thread.currentThread().getStackTrace();
        StringBuilder stringBuilder = new StringBuilder(100);
        stringBuilder.append(arr[2].getClassName())
                .append('(')
                .append(arr[2].getMethodName())
                .append(':')
                .append(arr[2].getLineNumber())
                .append(')');
        String method = stringBuilder.toString();
        logMessage.add("method", method);
        logMessage.add("message", message);
        logger.warn(logMessage.toString());
    }
}

封装这一层的目的有两个，一是为了保持和controller层和service层相同的日志规范，把traceId、spanid、cspanid加上。二是为了当error级别日志进行记录时，能够把错误信息直接发送到公司监测群中，这样可以及时对系统进行问题排查。

从上述的介绍中，可以看出日志记录的全链路是从controller获取到请求开始，进入到service层业务处理，再到具体代码中异常情况日志记录。同时使用traceId、spanid和cspanid进行全链路日志记录，

controller层 -> service层 -> 方法内部

0x02 接口类型

接口类型的不同，日志记录的便重点也会所有不一样。平时工作接触的接口类型应该也就是web接口和api接口。这两种类型的接口不同之处是一般web接口都是面向用户，需要登录的接口；而api接口则是面向其他系统，使用token进行认证。存在的差异也就是导致日志记录的要求有所不同。

web接口可能会有审计要求，需要记录下是谁在什么时候请求了什么数据、接口。这种类型的日志记录最合适的地方就是登录验证的filter中。

1
2
3
4
5
6
7
8
log_audit.info("auditlog||system=soc||hostIp=" + NetworkUtil.getRemoteHost((HttpServletRequest)request) 
    + "||userName=" + loginUser.getUsername() 
    + "||url=" + ((HttpServletRequest) request).getRequestURL() 
    + "||getParams=" + getQueryString 
    + "||postParams=" + postQueryString 
    + "||userIp=" + request.getRemoteAddr() 
    + "||timestamp=" + DateUtil.dateToStringCus(new Date(), DateUtil.DATE_FORMAT_SHORT) 
    + "||respose= ");

在filter中对用户进行登录认证，如果已经登录就可以直接记录下用户请求的相关信息。而如果用户请求的是API接口，则进行token认证，并记录下clientId等相关信息。

1
2
3
4
5
6
7
8
log_audit.info("auditlog||system=soc||hostIp=" + NetworkUtil.getRemoteHost((HttpServletRequest)request) 
    + "||userName=" + "api_client_" + clientId 
    + "||url=" + ((HttpServletRequest) request).getRequestURL() 
    + "||getParams=" + getQueryString 
    + "||postParams=" + postQueryString 
    + "||userIp=" + request.getRemoteAddr() 
    + "||timestamp=" + DateUtil.dateToStringCus(new Date(),DateUtil.DATE_FORMAT_SHORT) 
    + "||respose= ");

另外需要注意的是，这两个日志记录语句都没有记录response的值。为什么？因为获取不到返回值。由于返回流的特性，只能获取一次response中的返回值，如果这里获取了，那么接口中返回值就没了。request中的参数也有相同的问题。

当然这里贴的代码是系统进行日志修改之前的代码，之后的代码是可以获取到返回值的。改进的方式是给request和response加上一层包装，我们经常见的包装类Wrapper。这里就不细说了，之后会在另外一篇文章中详细说。

OK。上面就是我在系统开发过程中日志记录。可能不是特别的规范和完善，但是针对现在的问题，这种方式可以有效地帮助我定位、解决问题。