【51CTO.com原创稿件】前言
写代码的人就没有不写日志的，但我们到底该怎么打印日志，打印日志能不能有点章法?
针对这个问题，我查阅了《阿里巴巴Java开发手册》，里面有 8 条日志规约。比如不同作用的日志存放到不同的日志文件里，以 appName_logType_logName.log 方式进行命名。是挺不错，但属于是日志分类的问题，依旧解决不了程序员如何有章法的在代码中书写日志的问题。
探寻
先来看一个比较常见的日志打印示例：
- log.info("开始执行业务逻辑 ----------------->{}",param);
- log.info("业务逻辑执行中 ----------------->{}",param);
- log.info("结束执行业务逻辑 ----------------->{}",param);
- log.error("业务执行异常 ----------------->{}",param, e);
这种日志打印有什么问题？
第一、没有绑定事件
在执行什么业务逻辑呢？没有一个明确的事件，或者说是名字、归类，我更愿称之为事件。我们搜索日志时，是要有一个主语的，如果在日志打印中加入事件，我们搜索日志时，只需要输入关键字即可获取该事件的所有日志。改进后的⽇志打印：
- log.info("{}|开始执行业务逻辑 ----------------->{}",EVENT_NAME, param);
- log.info("{}|业务逻辑执行中 ----------------->{}",EVENT_NAME, param);
- log.info("{}|结束执行业务逻辑 ----------------->{}",EVENT_NAME, param);
- log.error("{}|业务执行异常 ----------------->{}",EVENT_NAME, param, e);
第二、没有绑定主键
一个事件下的日志无时无刻不在产生，而发生问题时，往往只会给你一个 case 进行诊断，所以，我们除了记录事件，还需要记录主键，通过观察这个主键在执行过程中都产生了哪些日志来定位问题。改进后的日志打印：
- log.info("{}|ID={}|开始执行业务逻辑 ----------------->{}",EVENT_NAME, ID, param);
- log.info("{}|ID={}|业务逻辑执行中 ----------------->{}",EVENT_NAME, ID, param);
- log.info("{}|ID={}|结束执行业务逻辑 ----------------->{}",EVENT_NAME, ID, param);
- log.error("{}|ID={}|业务执行异常 ----------------->{}",EVENT_NAME, ID, param, e);
第三、没有绑定请求
有了事件，有了主键，但是在查询日志的过程中，发现该主键产生了许多重复日志，日志的上下文不连贯，我们想看某一次请求产生的连续日志就非常不方便，这时候就需要考虑并发的情况。改进后的日志打印：
- // 可以使用 UUID 生成ReqId
- // final String ReqId = UUID.randomUUID().toString();
- log.info("{}|ReqId={}|ID={}|开始执行业务逻辑 ----------------->{}",EVENT_NAME, ReqId, ID, param);
- log.info("{}|ReqId={}|ID={}|业务逻辑执行中 ----------------->{}",EVENT_NAME, ReqId, ID, param);
- log.info("{}|ReqId={}|ID={}|结束执行业务逻辑 ----------------->{}",EVENT_NAME, ReqId, ID, param);
- log.error("{}|ReqId={}|ID={}|业务执行异常 ----------------->{}",EVENT_NAME, ReqId, ID, param, e);
第四、没有绑定分词符
不要在日志打印时使用 --- 这种分隔符，没意义、不标准，非常不好做分词。一定要将不变的文字说明和变化的参数用分词符分开打印，因为不变的文字说明也是可以成为关键词进行搜索的。改进后的日志打印：
- log.info("{}|ReqId={}|ID={}|开始执行业务逻辑|参数={}",EVENT_NAME, ReqId, ID, param);
- log.info("{}|ReqId={}|ID={}|业务逻辑执行中|参数={}",EVENT_NAME, ReqId, ID, param);
- log.info("{}|ReqId={}|ID={}|结束执行业务逻辑|参数={}",EVENT_NAME, ReqId, ID, param);
- log.error("{}|ReqId={}|ID={}|业务执行异常|参数={}",EVENT_NAME, ReqId, ID, param, e);
第五、错误日志需要输出异常信息
对于异常日志的打印一定要带上堆栈信息，异常堆栈不能使用 e.printStackTrace() 输出到控制台，这样异常堆栈是写入不了日志文件的，需要将异常对象写进最后的参数里，这点相信大家都懂。
除此之外，还需要将异常信息的 toString() 内容打印进同一行日志里。因为异常堆栈都是另起一行，对于一些单行日志记录的系统，比如阿里云sls，根本看不到异常信息，还得爬进服务器找日志堆栈。所以，还是很有必要将 e.toString() 写进参数里的，有些异常只看 e.toString() 的内容就可以定位了。为什么我这里要求使用 e.toString() 而不是 e.getMessage() ?因为如果是NullPointerException异常， e.getMessage() 返回空。改进后的代码：
- log.error("{}|ReqId={}|ID={}|业务执行异常|参数={}|e={}",EVENT_NAME, ReqId, ID, param, e.toString(), e);
第六、若有循环，需要绑定循环主键
将上面例子加个业务上的循环，再来看下代码：
- log.info("{}|ReqId={}|ID={}|开始执行业务逻辑|参数={}",EVENT_NAME, ReqId, ID, param);
- for (Key key : KeyList) {
- log.info("{}|ReqId={}|ID={}|业务逻辑执行中|参数={}",EVENT_NAME, ReqId, ID, param);
- }
- log.info("{}|ReqId={}|ID={}|结束执行业务逻辑|参数={}",EVENT_NAME, ReqId, ID, param);
这样产生的日志，非常不方便定位到具体的某次循环。如果循环体内出了异常，也不清楚具体是哪个Key 引发的。所以，遇到业务逻辑位于循环内的代码，应该打印出每次处理的 Key。改进后的代码：
- log.info("{}|ReqId={}|ID={}|开始执行业务逻辑|参数={}",EVENT_NAME, ReqId, ID, param);
- for (Key key : KeyList) {
- log.info("{}|ReqId={}|ID={}|Key={}|业务逻辑执行中|参数={}",EVENT_NAME, ReqId, ID, key, param);
- }
- log.info("{}|ReqId={}|ID={}|结束执行业务逻辑|参数={}",EVENT_NAME, ReqId, ID, param);
公式
经过上面的分析之后，我们可以总结出日志打印的公式：
- EVENT_NAME={}|ReqId={}|Key={}|childKey={}|doing something|result={}
如果没有过程的话，ReqId 是可以省略的，Key 的数量也不一定只是一个，你也可以看情况给日志加一列 [start|end] ，表示业务过程的开始和结束。
JSON日志
之前有段时间写过 JSON 格式的日志，就是每一个行日志都是一个 JSON 串，上面讲到的日志可以称为单行日志。
举个例子：
- Map<String, Object> logMap = new HashMap<>();
- try{
- logMap.put("EVENT_NAME", "monitor");
- // ....
- }finally {
- LogUtil.save(JSON.toJSONString(logMap));
- }
输出日志(为了方便查看，我已格式化)：
- {
- "EVENT_NAME": "monitor",
- "ReqId": "654321",
- "ID": "123456",
- "success": true,
- "param": {
- "name": "zs",
- "age": 14
- }
- }
JSON 日志天然绑定了请求过程，它最大的优势是输出序列化好的 JSON 串，非常方便离线对其各种操作。但对比于单行日志，代码嵌入性太高，需要通过 try..finally 代码块进行捕捉。
PS：以前我喜欢用 JSON 日志，现在我更喜欢用单行日志
【51CTO原创稿件，合作站点转载请注明原文作者和出处为51CTO.com】
