概述

日常工作中，程序員需要經(jīng)常處理線上的各種大小故障，如果業(yè)務(wù)代碼沒打印日志或者日志打印的不好，會極大的加大了定位問題的難度，使得解決bug的時間變長了。對于那種影響比較大的bug，處理時間是分秒必爭的，慢幾秒處理完，可能GMV就嘩啦啦的掉了很多。

一個程序員是否優(yōu)秀，其中一個判斷維度就是：處理線上問題是否快狠準，而其中日志是幫我們快速定位問題的絕佳手段。

下面分享一下筆者平時在業(yè)務(wù)系統(tǒng)里記日志的一些手法和習(xí)慣，希望對大家有一些幫助。

請統(tǒng)一日志格式

日志格式最好是統(tǒng)一的，即方便查看定位問題又方便統(tǒng)計收集。我一般喜歡定義一個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: 調(diào)用鏈id
eventName: 事件名稱,一般就是業(yè)務(wù)方法名稱
userId: C端用戶id
msg: 結(jié)果消息
costTime: 接口響應(yīng)時間
request: 接口請求入?yún)?/section>
response: 接口返回值
others: 其他業(yè)務(wù)參數(shù)

使用鏈式的風(fēng)格，方便設(shè)置字段的值：

            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，作為一個統(tǒng)一的入口。另外可以使用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;
    }

這種方案呢，有個缺點，就是每個業(yè)務(wù)方法都得處理日志，更好的方案是使用aop加thread local的方式，將請求統(tǒng)一攔截且將返回值和請求參數(shù)串起來，這個網(wǎng)絡(luò)上的方案很多，這里就不闡述了。

對于對性能要求比較高的應(yīng)用，反而推薦第一種方案，因為使用aop，有一些性能損耗。像我之前在唯品會參與的商品聚合服務(wù)，用的就是第一種方案，畢竟每一秒要處理上百萬的請求。

日志里加入traceId

如果應(yīng)用中已經(jīng)使用了統(tǒng)一調(diào)用鏈監(jiān)控方案，且能根據(jù)調(diào)用鏈id查詢接口情況的，可以不用在代碼里手動加入traceId。如果應(yīng)用還沒接入調(diào)用鏈系統(tǒng)，建議加一下traceId，尤其是針對聚合服務(wù)，需要調(diào)用中臺各種微服務(wù)接口的。像聚合層下單業(yè)務(wù)，需要調(diào)用的微服務(wù)就有如下這么些：

營銷系統(tǒng)
訂單系統(tǒng)
支付系統(tǒng)

下單業(yè)務(wù)調(diào)用這些接口的時候，如果沒有使用traceId進行跟蹤的話，當下單失敗的時候，到底是哪個微服務(wù)接口失敗了，就比較難找。下面以小程序端，調(diào)用聚合層下單接口的例子作為展示：

//營銷系統(tǒng)
{
   "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,
      }
   }
}

//訂單系統(tǒng)
{
   "eventName":"orderservice/createOrder",
   "traceId":"createOrder_1575270928956",
   "msg":"success",
   "costTime":29,
   "userId":null,
   "request":{
      "skuList":[
         {
            "skuId":2222,
            "buyNum":1,
            "buyPrice":65900,
         }
      ],
   },
   "response":{
      "result":"200",
      "msg":"調(diào)用成功",
      "data":{
         "bigOrderId":"BIG2019",
         "m2LOrderIds":{
            "MID2019":{
               "88258135":"LIT2019"
            }
         }
      }
   }
}

//支付系統(tǒng)

{
   "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"
      }
   }
}

可以看到聚合層需要調(diào)用營銷、訂單和支付三個應(yīng)用的接口，調(diào)用的過程中，使用traceId為createOrder_1575270928956的串了起來，這樣我們只需要grep這個traceId就可以把所有相關(guān)的調(diào)用和上下文找出來。

traceId如何生成呢，一種簡單的做法是，使用System.currentTimeMillis() 加上業(yè)務(wù)接口名字，如：

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

加traceId會侵入到業(yè)務(wù)方法里，比如說：

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這些內(nèi)部的service方法，都需要加一個traceId字段，目前我覺得還好，要是覺得入侵了，也可以考慮thread local的方式，處理請求的時候，為當前線程存儲一下traceId，然后在業(yè)務(wù)方法里，再從當前線程里拿出來，避免接口方法里的traceId滿天飛。

往期推薦

老友記：華同學(xué)寫了本 RPC 的書，小伙子 niubility ~

社招或校招，一定看看這個公司名單列表！

Spring Boot 如何實現(xiàn)動態(tài)設(shè)置定時任務(wù)？

敏感數(shù)據(jù)，“一鍵脫敏”，Sharding Sphere 完美搞定

為什么 1/3 字節(jié)員工曾反對取消大小周？

-END-

↑ 點擊上方關(guān)注我公號 ↑

我是泥瓦匠，堅持分享編程，算法，Java 等干貨教程

一枚醫(yī)科大本科生，開源小作者，半吊子創(chuàng)業(yè)愛好者...

半吊子的自己在試錯，不知道以后會干什么，但享受現(xiàn)在的試錯，試錯給我驚訝的生活

喜歡公號的互動分享，感謝關(guān)注，路上遇見了你，同一小段時間之路，相伴 ~