【.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); 第四、没有绑定分词符 不要在日志打印时使用 --- 这种分隔符，没意义、不标准，非常不好做分词。一定要将不变的文字说明和变化的WordPress模板参数用分词符分开打印，因为不变的文字说明也是可以成为关键词进行搜索的。改进后的日志打印： 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 代码块进行捕捉。 主⻚：https://github.com/onblog PS：以前我喜欢用 JSON 日志，现在我更喜欢用单行日志 【原创稿件，合作站点转载请注明原文作者和出处为.com】 |
喜欢
讨厌