写给开发者：记录日志的10个建议

http://blog.jobbole.com/52018/

欢迎在新的一年来到我的博客。在一个巴黎devops maillist上回复了一个关于监控和日志监控之后，我想起了很久以前我的一个博客计划。

尽管在写这篇博文的时候，我是在负责运维工作，不过本文主要是写给开发者的。

对我来说，明白如何记录日志和记录什么，是软件工程师必须明了的最艰巨的任务之一。之所以这么说，是因为这项任务与预测（divination）类似，你不知道当你要调试的时候需要些什么信息……我希望这10个建议能帮助你更好地在应用程序中记录日志，让运维工程师们受益。:)

 

1. 你不应自己写log

绝对不要，即便是用printf或者是自己写入到log文件，又或自己处理logrotate。请给你的运维同志们省省心，调用标准库或者系统API来完成它。

这样，你可以保证程序的运行与其他系统组件好好相处，把log写到正确的位置或者网络服务上，而不需要专门的系统配置。

假如你要使用系统API，也就是syslog(3)，学习好怎么用它。

如果你更喜欢用logging库，在Java里面你有很多选择，例如Log4j，JCL，slf4j和logback。我最喜欢用slf4j和logback的组合，因为它们特别给力，而且相对地容易配置(还允许使用JMX进行配置或者重载配置文件)。

slf4j最好的是你可以修改logging控制台的位置。如果你在编写一个库，这会变得非常重要，因为这可以让库的使用者使用自己的logging控制台而不需要修改你的库。

其他语言当然也有多种logging库，例如ruby的Log4r，stdlib logger，和几近完美的Jordan Sissel’s Ruby-cabin。

如果你想纠结CPU占用问题，那么你不用看这篇文章了。还有，不要把log语句放在紧内部循环体内，否则你永远看不出区别来。

 

2. 你应在适当级别上进行log

如果你遵循了上述第一点的做法，接下来你要对你程序中每一个log语句使用不同的log级别。其中最困难的一个任务是找出这个log应该是什么级别

以下是我的一些建议:

• TRACE level: 如果使用在生产环境中，这是一个代码异味(code smell)。它可以用于开发过程中追踪bug，但不要提交到你的版本控制系统
• DEBUG level: 把一切东西都记录在这里。这在debug过程中最常用到。我主张在进入生产阶段前减少debug语句的数量，只留下最有意义的部分，在调试(troubleshooting)的时候激活。
• INFO level: 把用户行为(user-driven)和系统的特定行为(例如计划任务…)
• NOTICE level: 这是生产环境中使用的级别。把一切不认为是错误的，可以记录的事件都log起来
• WARN level: 记录在这个级别的事件都有可能成为一个error。例如，一次调用数据库使用的时间超过了预设时间，或者内存缓存即将到达容量上限。这可以让你适当地发出警报，或者在调试时更好地理解系统在failure之前做了些什么
• ERROR level: 把每一个错误条件都记录在这。例如API调用返回了错误，或是内部错误条件
• FATAL level: 末日来了。它极少被用到，在实际程序中也不应该出现多少。在这个级别上进行log意味着程序要结束了。例如一个网络守护进程无法bind到socket上，那么它唯一能做的就只有log到这里，然后退出运行。

记住，在你的程序中，默认的运行级别是高度可变的。例如我通常用INFO运行我的服务端代码，但是我的桌面程序用的是DEBUG。这是因为你很难在一台你没有接入权限的机器上进行调试，但你在做用户服务时，比起教他们怎么修改log level再把生成的log发给你，我的做法可以让你轻松得多。当然你可以有其他的做法:)

 

3. honor the log category

我在第一点中提到的大部分logging库允许指定一个logging类别。它可以分类log信息，并基于logging框架的配置，在最后以某一形式进行log或是不进行。

通常，Java开发者在log语句处使用完整，合格的类名作为类别名。如果你的程序遵循单一职责原则(Single responsibility principle，原文有误)，这种模式还不错。

在Java的logging库中，Log类别是按等级划分的，例如在com.daysofwonder.ranking.ELORankingComputation会匹配到顶级的com.daysofwonder.ranking。这可以让运营工程师配置一个对此类别下指定的所有ranking子系统作用的logging。如果需要的话，还可以同时生成子类别的logging配置。

拓展开来，我们讲解一下特定情况下的调试。假设你在做一个应答用户请求的服务端软件(如REST API)。它正在对my.service.api.<apitoken>进行log(其中apitoken用于识别用户)。那么你可以选择对my.service.api类别进行log，记录所有的api，或是对某违规API用户的my.service.api.<bad-user-api-token>进行log。当然这需要系统允许你在运行中修改logging配置。

 

4. 你应该写有意义的log

这可能是最重要的建议了。没有什么比你深刻理解程序内部，却写出含糊的log更糟了。

在你写日志信息之前，总要提醒自己，有突发事件的时候，你唯一拥有的只有来自log文件，你必须从中明白发生了什么。这可能就是被开除和升职之间的微妙的差距。

当开发者写log的时候，它(log语句)是直接写在代码环境中的，在各种条件中我们应该写入基于当前环境的信息。不幸的是，在log文件中并没有这些环境，这可能导致这些信息无法被理解。

解决这个情况(在写warn和error level时尤为重要)的一个方法是，添加辅助信息到log信息中，如果做不到，那么改为把这个操作的作用写下。

还有，不要让一个log信息的内容基于上一个。这是因为前面的信息可能由于(与当前信息)处于不同的类别或者level而没被写入。更坏的情况是，它因多线程或异步操作，在另一个地方(或是以另一方式)出现。

 

5. 日志信息应该用英语

这个建议可能有点奇怪，尤其是对法国佬(French guy)来说。我还是认为英语远比法语更简炼，更适应技术语言。如果一个信息里面包含超过50%的英语单词，你有什么理由去用法语写log呢

把英法之争丢一边，下面是这个建议背后的原因：

• 英语意味着你的log是用ASCII编码的。这非常重要，因为你不会真正知道log信息会发生什么，或是它被归档前经过何种软件层和介质。如果你的信息里面使用了特殊字符集，乃至UTF-8，它可能并不会被正确地显示(render)，更糟的是，它可能在传输过程中被损坏，变得不可读。不过这还有个问题，log用户输入时，可能有各种字符集或者编码。
• 如果你的程序被大多数人使用，而你又没有足够的资源做国际化，英语会成为你的不二之选。如果你有国际化，那么让界面与终端用户更亲近(closer)(这通常不会是你的log)
• 如果你国际化了你的log(例如所有的warning和error level信息)，给他们一个特定的有意义的错误码。这样，用户做与语言无关的搜索，找到相关信息。这种良好的模式已经在虚拟内存(VMS)操作系统中应用了很久，而我必须承认它非常有用。如果你曾经设计过这种模式，你还可以试试这种模式: APP-S-CODE 或者 APP-S-SUB-CODE，它们分别代表:
  APP: 应用程序的3字缩写
  S: 严重程度的1字缩写(例如D代表debug，I代表info)
  SUB: 这个code所从属的应用程序的子部分
  CODE: 一个数字代号，指定这个问题中的错误

 

6. 你应该给log带上上下文

没有什么比这样的log信息更糟的了

1	Transaction failed

或是

1	User operation succeeds

又或是API异常时:

1	java.lang.IndexOutOfBoundsException

没有相应的上下文，这些信息不过是噪音，它们不会对调试过程中有意义的数值或是空间起作用(add value and consume space)。

带上上下文的信息要有价值得多，例如:

1	Transaction 234632 failed: cc number checksum incorrect

或是

1	User 54543 successfully registered e-mail<a href="mailto:user@domain.com">user@domain.com</a>

又或是

1	IndexOutOfBoundsException: index 12 is greater than collection size 10

在上面这一例子中的异常，如果你想把它传播开， 确保在处理的时候带上与当前level相应的上下文，让调试更简单，如下一个java的例子:

1 2 3 4 5 6 7

public void storeUserRank(int userId，int rank，String game) {      try {           ...deal database ...      } catch (DatabaseException de) {           throw new RankingException("Can't store ranking for user "+userId+" in game "+ game + " because " + de.getMessage() );      } }

这样，rank API的上层客户端就可以有足够的上下文信息log这个error。更好的做法是让上下文成为exception的参数，而不是信息，如果需要的话，上层可以对它进行修正(use remediation)。

保留上下文的一个简单方法是使用一些java logging库的MDC实现。MDC是一个每线程关联数组(per thread associative array)。可以修改logger设置，让每一行log总是输出MDC内容。如果你的程序使用每线程模式，这可以帮助解决保留上下文的问题。这个java的例子对给定的请求，使用MDC记录每用户的信息:

1 2 3 4 5 6 7 8 9 10 11 12

class UserRequest {      ...      public void execute(int userid) {           MDC.put("user"，userid);             // ... all logged message now will display the user=<userid> for this thread context ...           log.info("Successful execution of request");             // user request processing is now finished，no need to log our current user anymore           MDC.remote("user");      } }

提示，MDC系统在异步logging模式中的表现并不好，例如Akka的logging系统。因为MDC是保存在一个每线程存储区域的，而且在异步系统中你无法保证在写入log的线程是有MDC的那一个。在这种情况下，你需要手动地使用每一个log语句来log这些上下文。

 

7. 你应该用机器可解析的格式来打日志

Log信息对人很友善，但是对机器就惨了。有时人工地读这些log文件并不足够，你需要进行一些自动化过程(例如通过警报和审查)。或是你想集中存储你的log，以进行搜索。

如下，如果你把log的上下文嵌在string中会发生什么:

1	log.info("User {} plays {} in game {}",userId,card，gameId);

这会生成这样的文本:

1	2013-01-1217:49:37,656[T1]INFOc.d.g.UserRequestUser1334563plays4ofspadesingame23425656

现在，如果你想使它可解析，你需要下面这个(未测试过的)正则表达式:

1	/User(\d+)plays(.+)ingame(\d+)$/

好了，这并不轻松而且容易出错，把它接入到你代码中已有的string参数中。

这个方法怎么样，我相信Jordan Sissel在他的ruby-cabin库中第一次介绍的: 在你的log里面加入机器可解析格式的上下文。我们上述的例子中这样可以使用JSON:

1	2013-01-1217:49:37,656[T1]INFOc.d.g.UserRequestUserplays{'user':1334563,'card':'4ofspade','game':23425656}

现在你的log分析器可以更容易地写入，更直接地索引，而且你可以释放logstash所有的威力。

 

8. 日志不宜太多或太少

这听着貌似很愚蠢。log的数量是有一个合适的平衡的。

太多的log会使从中获得有价值的东西变得困难。当人工地浏览这种十分混乱的log，尝试调试产品在早上3点的一个问题可不是一个好事。

太少的log，你可能无法调试问题: 调试就像在拼一个困难的拼图，你需要得到足够的拼块。

不幸的是，这没有魔法般的规则去知道应该log些什么。所以需要严格地遵从第一第二点，程序可以变得很灵活，轻松地增减log的长度(verbosity)。

解决这个问题的一个方法是，在开发过程中尽可能多地进行log(不要被加入用于程序调试的log所迷惑)。当应用程序进入生产过程时，对生成的log进行一次分析，根据所发现的问题增减log语句。尤其是在调试时，在你需要的部分，你可以有更多的上下文或logging，确保在下一个版本中加入这些语句(可以的话，同时解决它来让这个问题在记忆中保持新鲜)。当然，这需要运维人员和开发者之间大量的交流。

这是一个复杂的任务，但是我推荐你重构logging语句，如你重构代码一样多。这样可以在产品的log和它的log语句的修改中有一个紧密的反馈循环。如果你的组织有一个连续的交付进程的话，它会十分有效，正如持续的重构。

Logging语句是与代码注释同级的代码元数据。保持logging语句与代码相同步是很重要的。没什么比调试时获得与所运行的代码毫无关系的信息更糟了。

9. 你应该考虑阅读者

为什么要对应用程序做log

唯一的答案是，在某一天会有人去读它(或是它的意义)。更重要的是，猜猜谁会读它，这是很有趣的事。对于不同的”谁”，你将要写下的log信息的内容，上下文，类别和level会大不同。

这些”谁”包括:

• 一个尝试自己解决问题的终端用户(想象一个客户端或桌面程序)
• 一个在调试产品问题的系统管理员或者运维工程师
• 一个在开发中debug，或者在解决产品问题的开发者

开发者了解程序内部，所以给他的log信息可以比给终端用户的复杂得多。为你的目标阅读者调整你的表达方式，乃至为此加入额外的类别(dedicate separate catagories)。

 

10. 你不应该只为调试而log

正如log会有不同的阅读者，它也有不同的使用理由。即便调试是最显而易见的阅读log的目的，你同样可以有效地把log用在:

• 审查: 有时商业上会有需求。这可以获取与管理或者合法用户的有意义的事件。通常会有一些语句描述这个系统中的用户在做些什么(例如谁登录了，谁在编辑……)
• 建档: log是打上了时间戳的(有时是微妙级的)，可以成为一个为程序各部分建档的好工具。例如记录一个操作的开始和结束，你可以自动化(通过解析log)或是在调试中，进行性能度量，而不需要把这些度量加到程序中。
• 统计: 如果你每次对一个特定事件(例如特定的错误或事件)进行log，你可以对运行中的程序(或用户行为)进行有趣的统计。这可以添加(hook)到一个警报系统中去连续地发现大量error。

 

总结

我希望这可以帮助你生成更多有用的log。如果我忘记了一些必须的(对你而言)建议，请谅解。对了，如果你看了这篇博客之后并不能更好地进行log，我并不负责 

如果这10个建议还不够的话，尽管在评论中补充更多有用的建议。