别再乱打日志了，这样才是定位 bug 打日志的方式！

曾经终败给现在 2022-09-16 05:52 199阅读 0赞

# ![909e0cd9dcc83845b6763f9280bff5a1.png][] #

# 概述 #

--------------------

日常工作中，程序员需要经常处理线上的各种大小故障，如果业务代码没打印日志或者日志打印的不好，会极大的加大了定位问题的难度，使得解决`bug`的时间变长了。对于那种影响比较大的`bug`，处理时间是分秒必争的，慢几秒处理完，可能`GMV`就哗啦啦的掉了很多。

一个程序员是否优秀，其中一个判断维度就是：**处理线上问题是否快狠准**，而其中日志是帮我们快速定位问题的绝佳手段。

下面分享一下笔者平时在业务系统里记日志的一些手法和习惯，希望对大家有一些帮助。

--------------------

# 请统一日志格式 #

--------------------

日志格式最好是统一的，即方便查看定位问题又方便统计收集。我一般喜欢定义一个`LogObject`对象，里面定义日志的各个字段。例如：

import com.fasterxml.jackson.annotation.JsonInclude;
    import com.fasterxml.jackson.annotation.JsonInclude.Include;
    import com.fasterxml.jackson.annotation.JsonProperty;
    
    public class LogObject {
        @JsonProperty(index = 1)
        private String eventName;
    
        @JsonProperty(index = 2)
        private String traceId;
    
        @JsonProperty(index = 3)
        private String msg;
    
        @JsonProperty(index = 4)
        private long costTime;
    
        @JsonProperty(index = 6)
        private Integer userId;
    
        @JsonProperty(index = 7)
        private Object others;
    
        @JsonProperty(index = 8)
        private Object request;
    
        @JsonProperty(index = 9)
        private Object response;
    
    
        public String getEventName() {
            return eventName;
        }
    
        public LogObject setEventName(String eventName) {
            this.eventName = eventName;
            return this;
        }
    
        public Object getRequest() {
            return request;
        }
    
        public LogObject setRequest(Object request) {
            this.request = request;
            return this;
        }
    
        public Object getResponse() {
            return response;
        }
    
        public LogObject setResponse(Object response) {
            this.response = response;
            return this;
        }
    
        public String getMsg() {
            return msg;
        }
    
        public LogObject setMsg(String msg) {
            this.msg = msg;
            return this;
        }
    
    
    
        public long getCostTime() {
            return costTime;
        }
    
        public LogObject setCostTime(long costTime) {
            this.costTime = costTime;
            return this;
        }
    
    
        public Integer getUserId() {
            return userId;
        }
    
        public LogObject setUserId(Integer userId) {
            this.userId = userId;
            return this;
        }
    
        public Object getOthers() {
            return others;
        }
    
        public LogObject setOthers(Object others) {
            this.others = others;
            return this;
        }
    
        public String getTraceId() {
            return traceId;
        }
    
        public LogObject setTraceId(String traceId) {
            this.traceId = traceId;
            return this;
        }

*  `traceId`: 调用链id
 *  `eventName`: 事件名称,一般就是业务方法名称
 *  `userId`: C端用户id
 *  `msg`: 结果消息
 *  `costTime`: 接口响应时间
 *  `request`: 接口请求入参
 *  `response`: 接口返回值
 *  `others`: 其他业务参数

使用链式的风格，方便设置字段的值：

long endTime = System.currentTimeMillis();
                LogObject logObject = new LogObject();
                logObject.setEventName(methodName)
                         .setMsg(msg)
                         .setTraceId(traceId)
                         .setUserId(backendId)
                         .setRequest(liveRoomPushOrderReqDto)
                         .setResponse(response)
                         .setCostTime((endTime - beginTime));
    
                LOGGER.info(JSON.toJSONString(logObject));

当然最好还是封装出一个工具类出来,例如叫:`LogTemplate`，作为一个统一的入口。另外可以使用`JsonProperty`注解，指定字段的顺序，例如通过`index=1`，将`eventName`放置在最前面。

@JsonProperty(index = 1)
        private String eventName;

--------------------

# 将request和response放置在一起 #

--------------------

将请求和返回值，放置在同一条日志里，有个好处，就是非常方便查看上下文日志。如果打印成两条，返回值那条可能被冲到很后面，而且也得再做一次`grep`操作，影响效率。具体的日志如下：

{
       "eventName":"createOrder",
       "traceId":"createOrder_1574923602015",
       "msg":"success",
       "costTime":317,
       "request":{
          "uId":111111111,
          "skuList":[
             {
                "skuId":22222222,
                "buyNum":1,
                "buyPrice":8800,
             }
          ]
       },
       "response":{
          "code":0,
          "message":"操作成功",
          "data":{
             "bigOrderId":"BIG2019",
             "m2LOrderIds":{
                "MID2019":{
                   "22222222":"LIT2019"
                }
             }
          }
       }
    }

为了能拼成一条，有两种方案，一种是比较`low`的，直接在代码里使用`try catch finally`，例如：

@PostMapping(value = "/createOrder")
        public JsonResult createOrder(@RequestBody Object request) throws Exception {
            String methodName = "/createOrder";
            Integer backendId = null;
            String msg = "success";
            long beginTime = System.currentTimeMillis();
            String traceId = "createOrder_"+beginTime;
            JsonResult response = null;
            try {
                OrderCreateRsp orderCreateRsp = orderOperateService.createOrder(request, traceId);
                response = JsonResult.success(orderCreateRsp);
            }
            catch (Exception e) {
                msg = e.getMessage();
                LOGGER.error(methodName+",userId:"+backendId+",request:"+ JsonHelper.toJson(request),e);
                throw new BizException(0,"下单失败");
            }
            finally {
                long endTime = System.currentTimeMillis();
                LogObject logObject = new LogObject();
                logObject.setEventName(methodName)
                         .setMsg(msg)
                         .setTraceId(traceId)
                         .setUserId(backendId)
                         .setRequest(request)
                         .setResponse(response)
                         .setCostTime((endTime - beginTime));
    
                LOGGER.info(JSON.toJSONString(logObject));
            }
    
            return response;
        }

这种方案呢，有个缺点，就是每个业务方法都得处理日志，更好的方案是使用`aop`加`thread local`的方式，将请求统一拦截且将返回值和请求参数串起来，这个网络上的方案很多，这里就不阐述了。

对于对性能要求比较高的应用，反而推荐第一种方案，因为使用`aop`，有一些性能损耗。像我之前在唯品会参与的`商品聚合服务`，用的就是第一种方案，毕竟每一秒要处理上百万的请求。

--------------------

# 日志里加入traceId #

--------------------

如果应用中已经使用了统一调用链监控方案，且能根据调用链`id`查询接口情况的，可以不用在代码里手动加入`traceId`。如果应用还没接入调用链系统，建议加一下`traceId`，尤其是针对聚合服务，需要调用中台各种微服务接口的。像聚合层下单业务，需要调用的微服务就有如下这么些：

*  营销系统
 *  订单系统
 *  支付系统

下单业务调用这些接口的时候，如果没有使用`traceId`进行跟踪的话，当下单失败的时候，到底是哪个微服务接口失败了，就比较难找。下面以小程序端，调用聚合层下单接口的例子作为展示：

//营销系统
    {
       "eventName":"pms/getInfo",
       "traceId":"createOrder_1575270928956",
       "msg":"success",
       "costTime":2,
       "userId":1111111111,
       "request":{
          "userId":1111111111,
          "skuList":[
             {
                "skuId":2222,
                "skuPrice":65900,
                "buyNum":1,
                "activityType":0,
                "activityId":0,
             }
          ],
       },
       "response":{
          "result":1,
          "msg":"success",
          "data":{
             "realPayFee":100,
          }
       }
    }
    
    //订单系统
    {
       "eventName":"orderservice/createOrder",
       "traceId":"createOrder_1575270928956",
       "msg":"success",
       "costTime":29,
       "userId":null,
       "request":{
          "skuList":[
             {
                "skuId":2222,
                "buyNum":1,
                "buyPrice":65900,
             }
          ],
       },
       "response":{
          "result":"200",
          "msg":"调用成功",
          "data":{
             "bigOrderId":"BIG2019",
             "m2LOrderIds":{
                "MID2019":{
                   "88258135":"LIT2019"
                }
             }
          }
       }
    }
    
    //支付系统
    
    {
       "eventName":"payservice/pay",
       "traceId":"createOrder_1575270928956",
       "msg":"success",
       "costTime":301,
       "request":{
          "orderId":"BIG2019",
          "paySubject":"测试",
          "totalFee":65900,
       },
       "response":{
          "requestId":"test",
          "code":0,
          "message":"操作成功",
          "data":{
             "payId":123,
             "orderId":"BIG2019",
             "tradeType":"JSAPI",
             "perpayId":"test",
             "nonceStr":"test",
             "appId":"test",
             "signType":"MD5",
             "sign":"test",
             "timeStamp":"1575270929"
          }
       }
    }

可以看到聚合层需要调用营销、订单和支付三个应用的接口，调用的过程中，使用`traceId`为`createOrder_1575270928956`的串了起来，这样我们只需要`grep`这个`traceId`就可以把所有相关的调用和上下文找出来。

`traceId`如何生成呢，一种简单的做法是，使用`System.currentTimeMillis()` 加上业务接口名字，如：

long beginTime = System.currentTimeMillis();
     String traceId = "createOrder_"+beginTime;

加`traceId`会侵入到业务方法里，比如说：

public void createOrder(Object obj) {
      long beginTime = System.currentTimeMillis();
       String traceId = "createOrder_"+beginTime;
       pmsService.getInfo(obj,traceId);
       orderService.createOrder(obj,traceId);
       payService.getPrepayId(obj,traceId);
    }

像`pmsService`这些内部的`service`方法，都需要加一个`traceId`字段，目前我觉得还好，要是觉得入侵了，也可以考虑`thread local`的方式，处理请求的时候，为当前线程存储一下`traceId`，然后在业务方法里，再从当前线程里拿出来，避免接口方法里的`traceId`满天飞。

[909e0cd9dcc83845b6763f9280bff5a1.png]: /images/20220828/5dfd7f9a964044448c63fb242d364dbd.png