2018-02-07 如何记录日志


一、简介

在软件开发中,我们出于各种目的,需要将程序运行中的一些状态记录在日志中。
日志记录,并不是越多越好,也不是记录的越频繁越好,而是需要我们精心设计记录日志的时机、内容、格式(以方便后续解析、查询日志)等等。
本文简单介绍了记录日志的一些基本原则和注意事项,更具体的记日志的技巧、最佳实践、日志框架等请参考子文档 Go如何记录日志

二、记录日志的目的(why)

开发调试

目的是开发期调试程序使用,这种日志量比较大,且没有什么实质性的意义,只应该出现在开发期,而不应该在项目上线之后输出。

记录用户行为

这种类型的日志,记录用户的操作行为,用于大数据分析,比如监控、风控、推荐等等。这种日志,一般是给其他团队分析使用,而且可能是多个团队,因此一般会有一定的格式要求,开发者应该按照这个格式来记录,便于其他团队的使用。当然,要记录哪些行为、操作,一般也是约定好的,因此,开发者主要是执行的角色。

程序运行状况

记录程序的运行状况,特别是非预期的行为、异常情况,这种日志,主要是给开发、维护人员使用。什么时候记录,记录什么内容,完全取决于开发人员,开发者具有高度自主性。本文讨论的主要也是指这种类型的日志,因为作为一个服务端开发、运维人员,程序运行日志往往是解决线上问题的救命稻草。

系统、机器状况

比如网络请求、系统CPU、内存、IO使用情况等等,这种日志主要是给运维人员使用,生成各种更直观的展现形式,在系统出问题的时候报警。

三、日志的要素(what)

每条日志都可以被当作一个事件(event),纪录了该事件发生时各个信息:

时间

日志的时间可以包含多种含义,不同含义的时间传递不同的信息:

  1. 指事件发生的时间,而不是日志被打印的时间。该时间附近范围内,结合该事件及服务器的网络、CPU、IO等状况,可以了解他们之间的相关性,有助于分析事件发生的原因。
  2. 持续时间。例如网络请求的耗时、处理请求的各个阶段的耗时等。
  3. 事件发生的顺序。通过时间戳的顺序,了解到一系列事件的发生顺序。对多进程、多线程、分布式系统有帮助。

位置

事件发生在哪个模块、哪个文件、哪个函数、哪一行代码里。

级别

日志的重要程度。用于:

  1. 不同的环境(测试、生产)下,打印不同级别的日志
  2. 不同级别的日志产生不同级别的监控报警

内容

简明扼要的描述发生了什么样的事情。目的是通过日志本身,而不是重新阅读相关代码来搞清楚发生了什么事情。
例如:logger.warn('user_login failed due to unvalid_username')

唯一标识

不管是面向用户的服务、面向机器集群的服务,都需要一个唯一标识作为日志的主体,以方便查找该事件主体的其他信息。(很多元数据是不会记在日志里的,只会记一个唯一标识)
例如:logger.warn('user_login failed due to password, username %s', username)

事件上下文

除了时间、位置、级别、内容,其他的一些有用的信息。
例如:

  1. logger.warn('user_login failed due to wrong password, username %s', username)
  2. logger.warn('user_login failed due to invalid password, username %s', username)
  3. logger.warn('user_login failed due to empty password, username %s', username)
    为了获取更丰富的上下文,有些数据需要从 Nginx 那里获取并传给本服务,然后打印。参考:和日志相关的Nginx设置

格式化

将上述的各个信息按照固定的顺序打印出来,不仅方便查找(例如使用grep,sed,awk等),也方便收集日志的程序(ES)解析日志。

其他

根据各自的业务特点,还可以在日志中记录(包括、不限于):

  1. 错误次数
  2. 当前正在处理的请求数
  3. 处理的进度(33%,50%,78%。。。)
  4. IP
  5. 问题出现时的请求链接

四、记录日志的一些原则和技巧

使用框架或模块

Java : Log4jLog4j2Commons LoggingSlf4jLogback
Python 内置的 logging 模块
beego 框架里的 github.com/astaxie/beego/logs 模块
其他的一些Go的框架:

  1. Logrus: github.com/Sirupsen/logrus (Docker use this)
  2. github.com/op/go-logging
  3. github.com/golang/glog (from Google, implementation of their C++ glog library in Go)
  4. github.com/cihub/seelog

不能出错

记录日志的目的是为了方便发现问题,解决问题,那么就需要保证记录日志本身不能出错。
尤其是对于 Error、Fatal级别的日志,出现的概率低,所以要做好单元测试,以保证记录日志本身是没问题的,是不会影响正常业务的。

避免敏感信息

  1. 避免记录用户密码。
  2. 避免记录用户个人信息,如身份证号、手机号等。应该只在日志里记录该用户的唯一标识,然后根据该唯一标识去其他的系统(例如数据库)查看详细信息。

记录“不可能发生”的事件

虽然正常逻辑下,某些情况是永远都不可能发生的,但是还是需要给这些不可能发生的情况打印一条日志。
例如 条件语句里的 else,switch 里的 default,都需要进行防御式的编程,同时记录日志。

Lazy logging

日志本身是一个字符串,可以通过多种方式拼接而成。如果根据log level,该条日志不应被打印,那么就应该避免拼接这个操作,也应该避免字符串拼接里的函数的调用。
例如:

#coding=utf-8
import logging
 
logger = logging.getLogger('LazyLogging')
logger.setLevel(logging.DEBUG)
hander = logging.StreamHandler()
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
hander.setFormatter(formatter) 
logger.addHandler(hander)
 
def getUserCount():
    logger.info('getUserCount is called')
    return 1
 
logger.debug("There are " + str(getUserCount()) + " users logged in now.")
  1. log level 设置为 DEBUG(第5行),那么会先打印第12行,再打印第15行
  2. log level 设置为 INFO,依然会打印第12行,说明:
    1. 问题1: 即便没有打印第15行,依然生成了一个字符串
    2. 问题2: 而且调用了 getUserCount 这个函数
  3. 解决上述的问题1,可以把第15行修改为:
logger.debug("There are %s users logged in now.", getUserCount())
  1. 为了解决上述的问题2,一个办法是:
class lazyEval:
    def __init__(self, f, *args):
        self.func = f
        self.args = args
 
    def __str__(self):
        return str(self.func(*self.args))
 
logger.debug("There are %s users logged in now.", lazyEval(getUserCount))

Java里的方式:

logger.debug(``"There are {} users logged in now."``, () -> getUserCount());

目前Golang里也存在这样的问题,但是还没找到怎么做到 lazyLogging。
但是,可以看出上面的方式也不优雅,所以应当避免在打印日志时调用函数。

异步打印日志

互联网应用程序中,高并发下的写日志会带来大量的IO操作,从而影响正常服务的性能。这时候的记日志就需要专门的服务去做,例如把日志打到消息队列里,然后再写到磁盘上。

设置缓存

默认的日志是随时 flush 到console、文件里的,通过设置缓存进行批量操作,可以一定程度上优化服务性能。

对日志归档、分类

打印到一个文件里,会使得该文件越来越大,不方便查找。
按日志属性分类:access log,error log,
按日期归档:lathspell-api.2018-01-17.log,lathspell-api.2018-01-18.log
按大小切分:lathspell-api.2018-01-17.log.1,lathspell-api.2018-01-17.log.2,lathspell-api.2018-01-17.log.3 (避免文件太大)

参考文档

  1. 《程序那些事:日志记录的作用和方法》 http://www.infoq.com/cn/articles/why-and-how-log#
  2. 日志的艺术http://www.cnblogs.com/xybaby/p/7954610.html
  3. 《日志的设计》http://blog.csdn.net/songbaojie/article/details/1867502
  4. 《日志规范》http://blog.csdn.net/hzhxxx/article/details/10590907
  5. 《Log 日志规范》http://www.cnblogs.com/kofxxf/p/3713472.html
  6. 《我的编程习惯 - 日志建议》https://zhuanlan.zhihu.com/p/28629319
  7. 《程序调试的利器 - 日志》https://www.tuicool.com/articles/V7z26j
  8. 《日志处理》https://beego.me/docs/module/logs.md
  9. 《写给开发者:记录日志的10个建议》http://blog.jobbole.com/52018/
  10. 《The Art of Logging: Advanced message formatting》https://garygregory.wordpress.com/2015/10/08/the-art-of-logging-advanced-message-formatting/
  11. 《Twelve Go Best Practices》https://talks.golang.org/2013/bestpractices.slide#1
  12. 《Go Best Practices 2016》https://peter.bourgon.org/go-best-practices-2016/#logging-and-instrumentation
  13. 《Think differently about what to log in go best practices》https://www.loggly.com/blog/think-differently-about-what-to-log-in-go-best-practices-examined/
  14. 《7 Good Rules to Log Exceptions》http://codemonkeyism.com/7-good-rules-to-log-exceptions/
  15. 《Logging in Java》http://hugozhu.myalert.info/2013/02/28/logging-in-java.html
  16. 《Apache Commons Logging - JCL Best Practices》http://commons.apache.org/proper/commons-logging//guide.html#JCL_Best_Practices
  17. 《The Art of Logging》https://www.codeproject.com/Articles/42354/The-Art-of-Logging
最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 204,053评论 6 478
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 85,527评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 150,779评论 0 337
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,685评论 1 276
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,699评论 5 366
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,609评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,989评论 3 396
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,654评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,890评论 1 298
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,634评论 2 321
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,716评论 1 330
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,394评论 4 319
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,976评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,950评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,191评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 44,849评论 2 349
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,458评论 2 342

推荐阅读更多精彩内容