An overview of the
In daily work, programmers often need to deal with all kinds of online faults. If the business code does not print logs or the logs are not printed properly, it will greatly increase the difficulty of locating problems and make it take longer to solve bugs. For that kind of big bug, processing time is against the clock, slow a few seconds to finish processing, may be GMV hubbub dropped a lot. One of the dimensions of a good programmer is how quickly and accurately they deal with online problems, and logs are a great way to quickly locate problems. The following to share the author usually in the business system to keep a log of some techniques and habits, I hope to help you.
Please unify the log format
A unified log format is recommended to facilitate problem locating and statistical collection. I generally like to define a LogObject object that defines the fields of the log. Such as:
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;
}
Copy the code- TraceId: id of the call chain
- EventName: the eventName, usually the business method name
- UserId: indicates the ID of a C-terminal user
- MSG: result message
- CostTime: indicates the interface response time
- Request: indicates the interface request input parameter
- Response: Indicates the returned value of the interface
- Others: indicates other service parameters
Use chain style to easily set field values:
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));
Copy the codeIt is better to encapsulate a utility class, such as LogTemplate, as a unified entry point. Alternatively, you can use the JsonProperty annotation to specify the order of the fields, such as putting eventName first with index=1.
@JsonProperty(index = 1)
private String eventName;
Copy the codePut request and Response together
Putting the request and return values in the same log has the advantage of making it very easy to view the context log. If you print in two, the return value might be flushed far back, and you’d have to do another grep, affecting efficiency. The 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" : "successful", "data" : {" bigOrderId ":" BIG2019 ", "m2LOrderIds" : {" MID2019 ": {" 22222222" : "LIT2019"}}}}}Copy the codeThere are two ways to do this. The first is the low one, which uses a try catch finally directly 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; }Copy the codeThe disadvantage of this approach is that each business method has to handle logging. A better approach is to use AOP plus Thread Local to block requests and string together the return values and request parameters. There are many alternatives on this network that I will not describe here.
For performance-critical applications, the first option is recommended because there are some performance costs associated with using AOP. For example, the product aggregation service I participated in in Vipshop used the first solution, after all, there are millions of requests to be processed every second.
Example Add traceId to logs
If the unified call chain monitoring scheme is used in the application and the interface status can be queried based on the call chain ID, you do not need to manually add traceId to the code. If the application is not connected to the call chain system, it is recommended to add traceId, especially for aggregation services that need to invoke various micro-service interfaces in the middle platform. Like the aggregation layer order business, the microservices that need to be called are as follows:
-
Marketing system
-
Order system
-
If traceId is not used to track when the payment system invokes these interfaces when placing orders, it will be difficult to find which microservice interface fails when the order fails. The following is an example of calling the single interface of aggregation layer on the small program side:
{ “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" : "the call is successful", "data" : {" bigOrderId ":" BIG2019." "m2LOrderIds":{ "MID2019":{ "88258135":"LIT2019" } } } } }Copy the codePayment system:
{ "eventName":"payservice/pay", "traceId":"createOrder_1575270928956", "msg":"success", "costTime":301, "Request" : {" orderId ":" BIG2019 ", "paySubject" : "test", "totalFee" : 65900}, "response" : {" requestId ":" test ", "code" : 0. "Message" : "successful", "data" : {" payId ": 123," orderId ":" BIG2019 ", "tradeType" : "the JSAPI", "perpayId" : "test", "nonceStr" : "test", "appId":"test", "signType":"MD5", "sign":"test", "timeStamp":"1575270929" } } }Copy the codeAs you can see, the aggregation layer needs to call the interfaces of marketing, order, and payment applications. During the call process, traceId is used to string createOrder_1575270928956, so we just need to grep this traceId to find all relevant calls and contexts. A simple way to generate a traceId is to use System.currentTimemillis () with the business interface name, such as:
long beginTime = System.currentTimeMillis();
String traceId = "createOrder_"+beginTime;
Copy the codeAdding traceId intrudes into business methods, such as:
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);
}
Copy the codePmsService (pmsService, pmsService, pmsService, pmsService, pmsService, pmsService, pmsService, pmsService, pmsService, pmsService, pmsService, pmsService, pmsService, pmsService, pmsService) Remove it from the current thread to prevent traceId from flying around in the interface method.