如何打造像样的应用日志——10条秘诀

我们的JCP小伙伴，Tomasz Nurkiewicz最近贴了关于几篇应用logging的文章，写的很有趣，我们决定将这些帖子整理一下，和大家分享。下面就是他给出的一些秘诀，希望可以让你的logs变得整洁又有用。

(注：为了您读起来朗朗上口，我们对原帖进行了小小的修改。)

1)工欲善其事，必先利其器

许多程序猿好像已经忘记logging程序行为和当前活动的重要性了。在某人把下面这段写进代码，并自得其乐的时候，他可能根本没有意识到log在代码维护，程序优化以及故障排查时的重要性。低估logs的价值，您可是大错特错了。

log.info("Happy and carefree logging");

在我看来，SLF4J是当今最棒的loggingAPI，因为它很好的支持了模式替换（ pattern substitution ），例如，在SLF4J中，你可以这么写：

log.debug("Found {} records matching filter: '{}'", records, filter);

但是在Log4J里面你必须这么写：

log.debug("Found " + records + " records matching filter: '" + filter + "'");

使用Log4J不仅仅语句更长，可读性更差，更多的是因为大量使用了字符串的连结导致性能降低。SLF4J添加了非常友好的替换特性。而且，由于不使用字符串连结，在logging语句进行过滤时也不调用toString()函数，因此就没有必要再使用isDebugEnabled()。顺便提一下，请注意filter string参数两边的单引号。

SLF4J只是一种外观模式，至于实现我推荐Logback框架，而不是Log4J。相比于Log4J而言，Logback开发了许多更加有趣的特性。

最后要介绍的的Perf4J，它们的宣言是(译者注：关于宣言的意思，可以查看Perf4J官网的详细介绍，大致意思是程序员喜欢println来发现异常，使用currentTimeMillis来计算程序耗时，因此，下面的意思就是Perf4J是用来衡量程序性能的，而Log4J是用来发现程序问题的)：

Perf4J is to System.currentTimeMillis() as log4j is to System.out.println()

我曾经在一个高负荷应用程序中使用Perf4J，也见过不少其他实战案例。管理员和用户都觉得Perf4J提供的图标非常惊艳，让我们可以立刻发现性能缺陷。关于Perf4J我们可以单独写一篇文章来讨论，目前你只需要看看他们的开发者手册就可以。

此外，Ceki Gulcu(Log4J，SLF4J以及Logback项目的创始人)对于如何摆脱commons-logging的依赖给出了一个简单的实现方法。(点击查看)

2)logging级别时刻记心中

每当在代码中写下logging语句时，你总是绞尽脑汁去想这里应该用什么级别的logging，是不是这样？事实上，90%的程序猿从不在意logging级别，他们只是简单的用相同的logging级别，要么INFO，要么DEBUG。为什么会这样呢？logging框架相对于System.out来说至少有两点好处：分类、分级。logging框架的这种特性，让你可以永远的或者在调试时选择性的过滤部分语句。要是你真的不太理解其中的差异，那么建议你把下面的东西打印出来，然后在IDE中输入"log."之前好好的瞧一瞧：

ERROR ——发生非常严重的错误，必须立刻检查出错的原因。任何IT系统都不能容忍这个级别的错误。例如：空指针异常，数据库不可用，关键任务停止。

WARN ——程序也许可以继续执行，但是需要特别关注。事实上，我将WARN分为两个级别：一个是常见的很明显的问题（例如：当前数据不存在，使用缓存值），另一个是可能出现的问题或建议。例如：“Application running in development mode”或是 “Administration console is not secured with a password”。程序可以容忍这些警告信息，但是这些信息必须是合理的，而且经过检查的。

INFO ——重要的业务流程结束了。理想情况下，管理员或者高级用户应该可以看懂INFO信息，并且可以很快搞清楚程序在做什么。例如，如果一个程序用来订购机票，对每张机票来说，都应该有一个INFO语句用来打印下面的信息“谁订购了哪里飞往哪里的机票”。关于INFO信息，还有一个说法就是，每个可能显著改变程序状态的动作都应该使用INFO语句打印出来（如数据库更新、外围系统的请求）。

DEBUG ——开发人员才使用的。下面的内容中会提到什么样的信息应该使用DEBUG来进行log。

TRACE ——TRACE会打印非常详细的信息，只有开发时才会使用。可能在产品上线之后的一段时间内，你会留意trace信息，但是这些log语句只是暂时的，都会渐渐关闭。DEBUG和TRACE很难区别开来，但是，如果你只是为了暂时记录下日志，并在开发测试完成之后去掉这些日志的话，那最好还是用TRACE。

上面这些只是一个建议，你也可以按照自己的准则来设计，只要有就好了。我的经验是，将所有信息都不做过滤的记录下来，但是必要时候必须能快速对日志进行过滤，并且提取出相应等级的信息，关键时候可以帮上大忙。

最后要说到的是大名鼎鼎的”*Enabled()“条件，有人喜欢在每句logging语句前面加上类似的判断：

if(log.isDebugEnabled())
    log.debug("Place for your commercial");

个人看来，这个习惯应该避免。这个语句对于性能的改进 微乎其微 （尤其是使用之前提到的SLF4J的替换模板），而且，看起来更像是一个不成熟的优化。此外，你能看出重复的地方么？只有极少数情况，在非常特定的条件下，才可以证明构造logging信息是非常耗费成本的。其他大部分情况下，你只需要做完你的logging工作，其他的让logging框架去完成就好了。

3) 你在logging什么？

每当你写了一个logging语句，请稍微花点时间看看你的log文件中记录的到底是什么。过一段时间之后，看看日志文件，看看有没有什么不正常的语句。首先，要避免logging语句中的空指针:

log.debug("Processing request with id: {}", request.getId());

你确定上面的request不会为null么？
还有一个容易出问题的地方是集合类。在使用Hibernate从数据库中读取域对象，并且不经意的写下下面的logging语句时 ：

log.debug("Returning users: {}", users);

SLF4J只有在语句确实打印的时候，才会调用集合类的toString方法，这很好。但是，调用的时候，内存溢出、N+1选择异常、线程死锁、延迟初始化异常、日志存储满等都可能出现。

更好的做法应该是这样，只logging域对象的id或者集合类的size。但是，从一组拥有getId方法的对象集合中生成id的集合的复杂程度是难以想象的，而且用java是非常难处理的。Groovy有很棒的展开操作符，在java里面我们可以使用commons beanutils类来实现这个一功能

log.debug("Returning user ids: {}", collect(users, "id"));

代码中的collect方法可以这么实现：

public static Collection collect(Collection collection, String propertyName) {
    return CollectionUtils.collect(collection, new BeanToPropertyValueTransformer(propertyName));
}

最后要一点是toString的错用或者不合理实现。首先，对于出现在logging语句中的每个类都要创建toString方法，优先使用ToStringBuilder。其次，小心数组和非典型集合类。数组和某些集合类可能没有实现对集合中所有元素依次toString的方法。对于数组，你可以使用Arrays工具类的deepToString方法。要经常查看日志，这样可以发现格式不正确的日志信息。

4) 避免副作用

logging语句应该对程序的行为产生不产生影响或者很小的影响。最近，一个老友给我看了一个东西，这个系统只有在某些特定环境下运行时才会跑出Hibernate的延迟初始化异常。你大概已经猜到，有些logging语句在连接会话时会造成垃圾回收的延迟。在这个系统环境下，日志级别增加，垃圾回收不能正确初始化。可以想象一下如果没有在别的环境下部署的经验，单纯的在这个环境下查找bug需要花费多少时间？

另外一种副作用是降低程序的运行速度。如果log太多信息，或者toString方法使用的不恰当，又或者使用了太多的字符串连接，那么log就会影响性能。这种影响有多大呢？我曾碰到一个案例，服务器每15分钟就要重启一次，罪魁祸首就是过度的logging导致线程卡死。这是另外一个副作用。从我个人经验来看，每小时几百MiB大概是log的极限了。

当然，如果logging语句发生异常，并且导致应用程序崩溃，当然也是非常大的副作用。我看到有人试图使用下面的语句来避免崩溃的发生：

 

try {
    log.trace("Id=" + request.getUser().getId() + " accesses " + manager.getPage().getUrl().toString())
} catch(NullPointerException e) {}

上面是真实存在的代码，但是为了世界更美好，请不要这么做，永远都别。

5) 简约而不简单

logging语句应该包含数据和描述两方面。例如：

log.debug("Message processed");
log.debug(message.getJMSMessageID());
 
log.debug("Message with id '{}' processed", message.getJMSMessageID());

在一个不熟悉的程序中进行调试时，你会使用上面哪段代码？请相信，上面两个其实没差，都很一般 。 再看另外一种：

if(message instanceof TextMessage)
    //...
else
    log.warn("Unknown message type");

在警告语句中加入消息类型、消息id等等其他信息很难么？看到上面的信息，我只知道出了问题，但是什么地方出问题不知道？上下文是什么呢？

还有一种就是“魔法日志”。举个例子：某个团队中的很多程序员都知道“&&&!#”后面跟上一些字符串就表示“收到id为xyz的消息”。没人想过去修改一下log的方式，他只是随机在键盘上敲了几下，觉得“&&&!#”还不错，就这么用了，而且，这种字符对于他个人而言找起来也是比较容易的。

结果，整个日志文件看起来像是随机字符串序列。甚至有人可能会认为它是Perl程序也不一定呢。事实上，日志文件应该易读、整洁而且描述性很强。不要使用魔法数，把值、数字、id以及上下文记录下来。展示正在处理的数据以及数据的意思，以及程序确切在做的事情。好的日志甚至可以当成程序代码的文档。

我有没有提到不要将密码或者其他隐私记录下来？千万别！

6) 优化pattern

Logging Pattern是非常棒的工具，它显式地为你的logging语句添加了有意义的上下文，但是要在Pattern中加入哪些信息是需要仔细考虑的。例如，如果日子每小时滚动一次，而且日志文档名又已经包含了日期时间，那么日期就没什么意义了。相反，在多线程中，如果线程的名称没有logging，那么你很难通过log进行跟踪——因为log会交叉重叠。在单线程的程序中倒是可以正常运用，但是单线程的程序基本不存在了。

以我个人经验来看，理想的logging pattern应该包括：当前时间(不包含日期，精确到毫秒)，logging等级，线程名称，logger名称以及logging信息。在Logback里面，代码大概是这个样子的

 

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>%d{HH:mm:ss.SSS} %-5level [%thread][%logger{0}] %m%n</pattern>
    </encoder>
</appender>

在pattern中不应该含有文件名，类名以及行号，虽然这几种信息很有诱惑力。我曾在代码中看到空的log语句:

 

log.info("");

之所以会出现空log语句，是因为写这句代码的程序员想当然的认为logging pattern是一定会有行号的，而且他清楚的知道“如果空的logging信息出现在文件的第67行（位于 authenticate()方法之内），就意味着用户鉴权通过。另外要说的是，logging类名、方法名称以及行号对性能有很大影响。

logging框架有一个更为高级的特性：映射诊断上下文(Mapped Diagnostic Context)。这个映射由本地线程管理。你可以将键值对放进这个映射，然后该线程中下达的每个logging语句都会包含这个值，它将成为pattern的一部分。

7) 方法的入参和返回值应该Log下来

在开发中查找bug的时候，通常你会进入调试器，然后尝试找到可能的原因。但是，考虑不允许你调试的情况。例如，BUG是在许多天之前发生的，而现在你只有log可以查看，你能找出什么头绪来么？

如果你能坚持logging每个方法的入参和处参，你甚至不需要调试器。当然，有些方法是需要考虑下到底要不要log的，比如访问外部系统（数据库也算），线程block、线程等待之类。你完全可以直接使用下面的pattern：

public String printDocument(Document doc, Mode mode) {
    log.debug("Entering printDocument(doc={}, mode={})", doc, mode);
    String id = //Lengthy printing operation
    log.debug("Leaving printDocument(): {}", id);
    return id;
}

因为你从头到尾记录下了方法的调用，你可以发现效率较低的代码，甚至可以发现死锁或者线程互斥的原因——只需找到只“进”不“出"的语句即可。而且，如果你的方法取名都比较符合语义，那日志也会赏心悦目。另外，分析哪里出了问题也变得简单，因为你清楚的知道每一步发生了什么。你甚至可以使用AOP来log一大堆方法，这样可以减少重复代码，但是使用的时候要小心，因为日志文件可能会很大。

最好还是考虑一下使用DEBUG或者TRACE级别。如果觉得有些方法调用频率太高有损性能，只需要将类的logging级别调低即可或者干脆不对这些类记录日志。但是，日志多些总比日志太少要好些。可以将logging语句和单元测试做一个比较——代码如果有单元测试用例，那么他最好也有logging语句。一个系统没有哪个部分是可以一点日志都不需要记录的。请记住，有时候，翻看日志是辨别程序正常运行还是瘫痪的唯一手段。

8) 注意外围系统

这是从上一个秘诀中引申出来的：如果有和外围系统交互，最好记下所有从外系统得到的信息和输入的信息。信息系统之间的整合是很难搞定的，而且，在两个系统之间进行问题诊断也非常的困难（想象一下：不同厂家、不同系统环境和团队等等）。例如，我们最近发现将所有的消息内容都记录下来对于系统整合和测试是很有好处的，我们甚至将CXF webservice中SOAP和HTTP请求头都记录下来了。

这样的日志开支可能很大，如果确实影响性能，你可以随时禁用这些logging。但是，一个速度很快但是一旦坏掉就没人能修好的系统有什么意义呢？和外围系统整合时，要非常小心，而且要准备好付出相应的代价。如果你有幸通过ESB进行整合，那么ESB可能是记录request和response的最佳地点。

有些时候，和外围系统交互的信息量太大，记录下所有信息可能不太现实。但是，在测试阶段以及投入使用后的一段时间内，我们愿意将所有信息都记录下来，而且做好了付出代价的准备。通过logging级别的设置，可以很容易做到。不妨看看下面的代码：

 

Collection<Integer> requestIds = //...
if(log.isDebugEnabled())
    log.debug("Processing ids: {}", requestIds);
else
    log.info("Processing ids size: {}", requestIds.size());

如果logger设置的是记录DEBUG信息，上面的代码会打出有关requestIds的所有的内容，但是如果设置的是记录INFO信息，日志中只会输出requestIds的size。这里还要提一下，requestIds 这个集合不能为空。尽管在DEBUG级别会正常记录，但是在INFO级别时会跑出空指针异常，还记得秘诀4中提到的副作用吧？

9) 正确的记录异常

首先，避免logging异常，异常的记录工作让框架或者容器去完成。当然也有例外：如果你从一些远程服务（如RMI，EJB remote session Bean）中抛出异常，这些服务可以序列化异常，那一定要让客户端可以捕获。不然的话，客户端会捕获NoClassDefFoundError之类的奇怪异常，而不是真正的异常原因。

记录异常是logging最重要的功能之一，但是很多程序员倾向于将logging当成处理异常的手段。有时候只是返回默认值（空值或者空字符串），装作什么都没发生。有时候，他们会先记下异常信息，然后将异常包装一下又抛出去。

log.error("IO exception", e);
throw new MyCustomException(e);

上面的这种代码结构通常会将相同的stack trace打印两遍，因为总有什么地方会捕获MyCustomException，然后记下导致MyCustomException的原因。要么log出异常的原因，要么包装然后抛出异常，如果同时做两件，log就会变的很混乱。

如果确实需要log异常信息呢？出于某种原因，我见过的logging语句大概有一半是错的。来个快速测验，下面哪句log语句可以正确的记下空指针异常？

try {
    Integer x = null;
    ++x;
} catch (Exception e) {
    log.error(e);        //A
    log.error(e, e);        //B
    log.error("" + e);        //C
    log.error(e.toString());        //D
    log.error(e.getMessage());        //E
    log.error(null, e);        //F
    log.error("", e);        //G
    log.error("{}", e);        //H
    log.error("{}", e.getMessage());        //I
    log.error("Error reading configuration file: " + e);        //J
    log.error("Error reading configuration file: " + e.getMessage());        //K
    log.error("Error reading configuration file", e);        //L
}

不可思议，只有G和L是正确的，L更好一些。A和B在SLF4J中根本不能编译，其他的要么没有打印stack trace，要么打印的信息不合适。例如，E不会打印任何东西，因为空指针异常通常不会提供任何异常信息，而且stack trace也不会打印。记住，第一个参数必须是文本信息，描述了问题的实质所在。不要在第一个参数中加入异常相关的信息，因为接下来会在stack trace前面自动打印出来。但是，要做到这些，必须将异常作为第二个参数。

10) 让log易读且易解析

一般说来，对log特别有兴趣的有两组受众：人（程序员也在此列）和电脑（通常是系统管理员写的shell脚本）。logs应该易读且容易理解，就像代码一样。换句话说，如果你的应用程序每两小时要生成1GB数据，没有哪个人或者什么可视化文本编辑器可以看得过来。这个时候grep，sed和awk就派上用场了。如果可能的话，尽量按下面的方式组织logging，产生让人和机器都很容易理解的log，例如，避免对数字的格式化、正则表达式容易识别的pattern等等。如果可能的话，可以将数据同时打印出两种格式：

log.debug("Request TTL set to: {} ({})", new Date(ttl), ttl);
// Request TTL set to: Wed Apr 28 20:14:12 CEST 2010 (1272478452437)
final String duration = DurationFormatUtils.formatDurationWords(durationMillis, true, true);
log.info("Importing took: {}ms ({})", durationMillis, duration);
//Importing took: 123456789ms (1 day 10 hours 17 minutes 36 seconds)

计算机是非常喜欢“1970 年 1 月 1 日午夜开始经过的毫秒数”这种时间格式的，而人看到 “1 day 10 hours 17 minutes 36 seconds” 这种格式也会很高兴。顺便说一句，可以看一下DurationFormatUtils，非常不错的工具。

就说这么多吧，一首logging秘诀狂想曲，来自我们的 JCP partner, Tomasz Nurkiewicz. 别忘记分享哦！