日志要认真写

曾经,我是不怎么关心程序里的日志的。每次写程序都是写完逻辑,顺带着在一些关键部位加一些日志记录。或者是在调试的过程中插入一些日志。在测试环境这么做完全没问题。因为整个环境只有我一个人在用,每次执行程序,只有那几条日志被打印出来而已。肉眼一扫就知道有没有问题了。工作中发现,很多人其实也是这样,随手写点日志,甚至根本不写日志。

糟糕的日志

直到有一天我需要检查一个问题,有反馈说某个用户收不到我们系统发出的消息。怎么回事呢?系统在线上运行了,也不能为了这一个个例停掉整个系统来调试吧?投递消息这里应该记录了日志,于是打开日志文件检查,看到了如下让人目瞪口呆的内容:

[2015-12-01 14:54:33][INFO] send message ok
[2015-12-01 14:54:33][INFO] send message fail
[2015-12-01 14:54:33][INFO] send message ok
[2015-12-01 14:54:34][INFO] send message ok
[2015-12-01 14:54:34][INFO] send message fail
[2015-12-01 14:54:35][INFO] send message ok

这谁写的日志给我站出来!你语文是体育老师教的吗?

老师从小就教导我们,叙述事情要讲清楚时间,地点,人物,事件。这一条日志你只写了个事件,时间都是框架帮你写好的,然后事件你还没讲清楚。有十个模块在发消息,我怎么直到这些日志是哪个模块写的?就算只有一个模块在记录这些日志,怎么能知道是发给谁的消息成功或者失败了?发送失败了,那么原因是什么?

详细的日志

有些同学没有意识到日志的作用。日志是用来记录事情的。它并不是给你调试用的工具,调试程序有专门的调试工具可以用。既然是描述事情的就需要具备上面至少四点:时间,地点,人物,事件。那么按照这个思路再来考虑一下日志应该怎么写。

时间一般的日志系统会自动加上。地点就可以写上哪个模块。人物可以写触发这个事件的主体。事件当然就描述发生了什么,详细程度可根据实际需要适当调整。修改后的日志写出来大概是这样:

[2015-12-01 14:54:34][INFO] SMS_Sender [verify] send message to [186XXXXZZZZ] ok
[2015-12-01 14:54:34][ERROR] SMS_Sender [verify] send message to [110] fail: invalid phone number

差不多就是这个意思。这两行日志比之前那种好得多,至少一眼看去直到是哪个模块在调用什么类型的过程时出了什么样的问题。正确的事件并不需要太多细节,而发生错误的事件我需要知道发生了什么样的错误。大部分情况下,这种详细程度的日志就足够应付生产环境的大部分问题了。

可追踪的日志

至于日志需要描述得多细致,还是需要根据实际情况去斟酌。比如我有一个支付系统,虽然我的数据库里也有支付记录,但是我还是需要日志来跟踪一些操作。那么,可能我在整个支付流程的日志中,每条都要加入一个唯一的ID。这样就可以根据这个ID来追踪程序的运行流程。

[2015-12-01 14:54:40][INFO] Pay [9cb3][generate] create order for user 1, id:36
[2015-12-01 14:54:40][INFO] Pay [9cb3][delay] checking status job dispatched for order id:36 
[2015-12-01 14:54:40][INFO] SMS_Sender [9cb3][verify] send message to [186XXXXZZZZ] ok

其他用途

有人会问,记这些东西除了出了问题查起来方便,还能有什么用?其实出了问题查找起来方便是日志主要作用。除了这个还能用来做告警,还能用来做统计分析。

用日志来做告警这个很容易理解,比如你在程序抛出异常的时候会写一条ERROR级别的日志。程序上线之后你总不能时刻盯着日志看吧。于是搞这么一个程序一直盯着日志,日志写一行它读一行,发现ERROR之后发个邮件也好发条短信也好,这就算是简单的告警了。有人说我在代码里植入报警不就可以了,为啥还要监控日志这么麻烦?我就笑笑不说话。

统计分析是怎么回事呢?还拿上面的支付系统来说吧。例如你想得到一个用户购买情况的实时报表,显示每个时段有多少笔订单。你可以说我实时去数据库里查,但是这样会给数据库增加额外的负担。有一种做法是把一些订单数据写到日志里,像用户id,金额,交易方式等等。然后,还是搞这么一个程序一直盯着日志,把订单相关的日志过滤出来,再用正则把需要统计的数据匹配出来,存储到一个专门用来出报表的数据库(其实完全可以把日志存成json格式)。

可能在很多年以前就有人这么用日志了,只不过最近ELK越来越成熟,这种用法才进入了更多人的视野。ELK就是ElasticSearch,LogStash和Kibana——LogStash用来收集日志,ElasticSearch做存储索引和搜索,Kibana用来展示图表。

总结

所以说,为什么日志要认真写?

Jerray Fu