1
summary
In daily work, programmers often need to deal with various online faults. If the business code does not print the log or the log is not printed well, it will greatly increase the difficulty of locating the problem and make the time to solve the bug longer.
For those bug s that have a great impact, the processing time is against the clock. If you finish processing a few seconds later, GMV may crash a lot.
One of the judging dimensions of whether a programmer is good or not is whether to deal with online problems quickly and accurately, and logs are an excellent means to help us locate problems quickly.
Let's share some techniques and habits of the author in recording logs in the business system, hoping to help you.
2
Please unify the log format
The log format should be unified, which is convenient for viewing and locating problems and collecting statistics. I generally like to define a LogObject object, which defines various fields of the log. For example:
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;
}- traceId: call chain id
- userId: C-end user id
- msg: result message
- costTime: interface response time
- Request: interface request input parameter
- response: interface return value
- others: other business parameters
Using the chain style, it is convenient to set the value of the field:
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));Of course, it's better to encapsulate a tool class, such as LogTemplate, as a unified entry.
In addition, you can use the JsonProperty annotation to specify the order of fields. For example, by index=1, put eventName at the top.
@JsonProperty(index = 1) private String eventName;
3
Put request and response together
Placing the request and return values in the same log has the advantage that it is very convenient to view the context log.
If it is printed into two pieces, the one with the return value may be rushed to the back, and the grep operation must be performed again, which will affect the efficiency.
Specific logs are as follows:
{
"eventName":"createOrder",
"traceId":"createOrder_1574923602015",
"msg":"success",
"costTime":317,
"request":{
"uId":111111111,
"skuList":[{
"skuId":22222222,
"buyNum":1,
"buyPrice":8800,
}]
},
"response":{
"code":0,
"message":"Operation succeeded",
"data":{
"bigOrderId":"BIG2019",
"m2LOrderIds":{
"MID2019":{
"22222222":"LIT2019"
}
}
}
}
}In order to form a line, there are two schemes. One is relatively low. Directly use try catch finally in the code, for example:
@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,"Order failed");
} 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;
}[one disadvantage of these schemes is that each business method has to process logs. A better scheme is to use aop plus thread local to intercept requests uniformly and string the return value and request parameters. There are many schemes on the network, which will not be described here.
For applications with high performance requirements, the first scheme is recommended instead, because aop has some performance loss. Like the commodity aggregation service I participated in in vipshop before, I used the first scheme. After all, I have to process millions of requests every second.
4
Add traceId to the log
If the unified call chain monitoring scheme has been used in the application and the interface can be queried according to the call chain id, there is no need to manually add traceId to the code.
If the application has not been connected to the call chain system, it is recommended to add traceId, especially for aggregation services, which need to call various micro service interfaces in the middle office. For example, the microservices that need to be called for ordering business in the aggregation layer are as follows:
- Marketing system
- Order system
- Payment system
When the order business calls these interfaces, if traceId is not used for tracking, it is difficult to find which microservice interface fails when the order fails. The following is an example of calling the single interface of the aggregation layer on the applet side:
Marketing system:
{
"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,
}
}
}Order system:
{
"eventName":"orderservice/createOrder",
"traceId":"createOrder_1575270928956",
"msg":"success",
"costTime":29,
"userId":null,
"request":{
"skuList":[
{
"skuId":2222,
"buyNum":1,
"buyPrice":65900,
}
],
},
"response":{
"result":"200",
"msg":"Call succeeded",
"data":{
"bigOrderId":"BIG2019",
"m2LOrderIds":{
"MID2019":{
"88258135":"LIT2019"
}
}
}
}
}Payment system:
{
"eventName":"payservice/pay",
"traceId":"createOrder_1575270928956",
"msg":"success",
"costTime":301,
"request":{
"orderId":"BIG2019",
"paySubject":"test",
"totalFee":65900,
},
"response":{
"requestId":"test",
"code":0,
"message":"Operation succeeded",
"data":{
"payId":123,
"orderId":"BIG2019",
"tradeType":"JSAPI",
"perpayId":"test",
"nonceStr":"test",
"appId":"test",
"signType":"MD5",
"sign":"test",
"timeStamp":"1575270929"
}
}
}You can see that the aggregation layer needs to call the interfaces of marketing, order and payment applications. In the process of calling, use traceId as createOrder_1575270928956 is concatenated so that we can find all relevant calls and contexts only by using the traceId grep.
How to generate traceId? A simple way is to use system Currenttimemillis() plus the name of the business interface, such as:
long beginTime = System.currentTimeMillis(); String traceId = "createOrder_"+beginTime;
Adding traceId will intrude into the business method, for example:
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);
}Internal service methods such as pmsService need to add a traceId field. At present, I think it's OK. If you think it's invaded, you can also consider thread local. When processing requests, store traceId for the current thread, and then take it out from the current thread in the business method to avoid traceId flying all over the world in the interface method.