日志到底应该怎么打印？

【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 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 代码块进行捕捉。

主⻚：https://github.com/onblog

PS：以前我喜欢用 JSON 日志，现在我更喜欢用单行日志

【51CTO原创稿件，合作站点转载请注明原文作者和出处为51CTO.com】