104 日志规范

前言#

日志用来记录用户操作、系统运行状态等,是一个系统的重要组成部分。然而由于日志并非系统核心功能,通常情况下并不受团队的重视。在出现问题需要通过日志来定位时,才发现日志还存在很多问题。

日志记录的好坏直接关系到系统出现问题时定位的速度,同时可以通过对日志的观察和分析,提前发现系统可能的风险,避免线上事故的发生。

1. 关于日志级别##

一个项目各个日志级别的定义应该是清楚明确的,是每个开发人员所遵循的;
即使是TRACE或者DEBUG级别的日志,也应该有一定的规范,要保证除了开发人员自己以外,包括测试人员和运维人员都可以方便地通过日志定位问题;

  • FATAL — 表示需要立即被处理的系统级错误。当该错误发生时,表示服务已经出现了某种程度的不可用,系统管理员需要立即介入。这属于最严重的日志级别,因此该日志级 别必须慎用,如果这种级别的日志经常出现,则该日志也失去了意义。通常情况下,一个进程的生命周期中应该只记录一次FATAL级别的日志,即该进程遇到无 法恢复的错误而退出时。当然,如果某个系统的子系统遇到了不可恢复的错误,那该子系统的调用方也可以记入FATAL级别日志,以便通过日志报警提醒系统管 理员修复。
  • ERROR — 该级别的错误也需要马上被处理,但是紧急程度要低于FATAL级别。当ERROR错误发生时,已经影响了用户的正常访问。从该意义上来说,实际上 ERROR错误和FATAL错误对用户的影响是相当的。FATAL相当于服务已经挂了,而ERROR相当于好死不如赖活着,然而活着却无法提供正常的服 务,只能不断地打印ERROR日志。特别需要注意的是,ERROR和FATAL都属于服务器自己的异常,是需要马上得到人工介入并处理的。而对于用户自己 操作不当,如请求参数错误等等,是绝对不应该记为ERROR日志的。
  • WARN — 该日志表示系统可能出现问题,也可能没有,这种情况如网络的波动等。对于那些目前还不是错误,然而不及时处理也会变为错误的情况,也可以记为WARN日 志,例如一个存储系统的磁盘使用量超过阀值,或者系统中某个用户的存储配额快用完等等。对于WARN级别的日志,虽然不需要系统管理员马上处理,也是需要 即使查看并处理的。因此此种级别的日志也不应太多,能不打WARN级别的日志,就尽量不要打。
  • INFO — 该种日志记录系统的正常运行状态,例如某个子系统的初始化,某个请求的成功执行等等。通过查看INFO级别的日志,可以很快地对系统中出现的 WARN,ERROR,FATAL错误进行定位。INFO日志不宜过多,通常情况下,INFO级别的日志应该不大于TRACE日志的10%。
  • DEBUG or TRACE — 这两种日志具体的规范应该由项目组自己定义,该级别日志的主要作用是对系统每一步的运行状态进行精确的记录。通过该种日志,可以查看某一个操作每一步的执 行过程,可以准确定位是何种操作,何种参数,何种顺序导致了某种错误的发生。可以保证在不重现错误的情况下,也可以通过DEBUG(或TRACE)级别的 日志对问题进行诊断。需要注意的是,DEBUG日志也需要规范日志格式,应该保证除了记录日志的开发人员自己外,其他的如运维,测试人员等也可以通过 DEBUG(或TRACE)日志来定位问题。

备注:
整个团队(包括测试人员)需要对日志级别有明确的规定,什么日志记入什么级别的日志,什么级别的错误出现要如何处理等

2. 对记录的日志要进行更新维护##

由于DEBUG(或TRACE)级别的日志对于定位问题至关重要,因此该种日志记录是否完备且不冗余、格式是否规范等也需要花费大量精力来优化。此处有以下几个比较好的实践:

  • 定义好整个团队记录DEBUG(或TRACE)日志的规范,保证每个开发记录的日志格式统一;
  • 整个团队(包括开发、测试)定期对记录的日志内容进行Review;
  • 开发通过在查问题的过程来优化日志记录的方式;
  • 测试在日志中发现的问题,都需要及时向开发人员反映;

备注:
需要定期对日志内容进行优化更新,目的就是通过日志快速准确的定位问题。

3. 关于日志分类##

日志从功能来说,可分为诊断日志、统计日志、审计日志。

诊断日志:

  • 请求入口和出口
  • 外部服务调用和返回
  • 资源消耗操作: 打开文件等
  • 容错行为: 譬如云硬盘的副本修复操作
  • 程序异常: 譬如数据库无法连接
  • 后台操作:清理程序
  • 启动、关闭、配置加载
  • 抛出异常时,不记录日志

统计日志:

  • 用户访问统计
  • 打点日志(如记录用户访问的页面,点击的按钮等)

审计日志:

  • 管理操作

将不同需求的日志记入到不同的日志文件中,可以方便相关问题(管理平台操作审计,用户操作计费等)的处理。针对每一种需求,需要对日志的格式,日志记录的内容等进行特别的记录。

备注:
要明确不同日志的用途,对日志内容进行分类

4. 日志中不要记录无用信息##

业务处理过程中可记可不记的日志,就尽量不要记到日志中,避免无用日志过多把重要日志淹没了。

例如:
资讯发布时检查是否已创建论坛贴子,如果未创建则不发表资讯。发布的时间点是在活动开始前,也就是说在活动开始前这个检查会一直不能满足,而下面这条日志会不断的出现,其实就是属于无效日志

Logger.warn("[ActiveNewsCreateHandler handle]专区活动需帖子发布后才能发布资讯,activeId[%s]", activeId);

备注:
绝不要打印没有用的日志,防止无用日志淹没重要信息

5. 日志记录信息要完整##

****推荐在日志中记录的内容:****

  • 在系统启动或初始化时记录重要的系统初始化参数
  • 记录系统运行过程中的所有的错误
  • 记录系统运行过程中的所有的警告
  • 在持久化数据修改时记录修改前和修改后的值
  • 记录系统各主要模块之间的请求和响应(如:调用外部接口的响应报文)
  • 重要的状态变化(如:发奖请求的状态变更)
  • 系统中一些长期执行的任务的执行进度

不推荐记录日志的内容

  • 函数入口信息 — 除非该函数入口表示了一个重要事件的开始,或者将该信息记入DEBUG级别日志
  • 文件内容或者 一 大段消息的内容 ,如果实在需要记录,则可以截取其中一些重要的信息来记入日志
  • 业务规则错误 — 现有的业务使用业务异常在控制流程,在不满足业务的场景下,程序抛出的业务异常,不应记录错误日志中,避免大量的报警邮件(这些邮件通常会被忽略掉)

备注:
日志信息要准确全面,能做到仅凭日志就可以定位问题。

6. 测试的日志##

测试代码(单元测试,接口测试等)的日志同样重要。特别是,当一个测试失败时,可以通过日志很快确定是测试代码有问题,还是系统出现了故障,如果做不到这一点,那就需要优化测试的日志了。

测试日志应该包含以下内容:

  • 测试执行的环境
  • 测试执行前的初始状态
  • 测试的详细步骤
  • 测试和系统的交互信息
  • 测试期望的返回结果
  • 测试实际的返回结果

备注:
应以同样严格的要求对待测试程序的日志

7. 从问题中完善日志##

在测试环境、线上环境出现问题的时候,需要尽快发现问题并解决,而同时,需要借此机会好好思考一下当前系统的日志是否合理。需要考虑以下问题:

  • 如果定位问题花费了很长时间,那就说明系统日志还存在问题,需要进一步完善和优化
  • 需要思考是否可以通过优化日志,来提前预判该问题是否可能发生(如某种资源耗尽而导致的错误,可以对资源的使用情况进行记录)

通过系统出现的问题来优化日志,应该是一项长期的实践,不断地从日志发现系统的问题,不断地从系统异常发现日志的问题。

备注:
日志的优化是一件持续不断需要投入精力的事,需要不断从错误中学习

8. 关于线上机器的日志级别##

正常情况下,线上的日志应开启INFO级别,如果需要定位线上问题可以临时启用DEBUG级别日志,定位到问题原因后,重新设置日志为INFO级别。

9. 上线后的日志观察##

版本刚上线后,开发人员需要通过对日志的观察来确定服务是否正常。

10. 日志格式##

整体系统的日志格式需要使用统一的格式输出,方便大家来定位线上问题。

以SDK的发奖流程日志举例:

  • 不满足业务规则的日志输出格式
public static final String LOG_TEMPLET = "request_id: %s, %s, json: %s";
Logger.warn(SDKAwardService.LOG_TEMPLET, wnr.requestId, "repeat request, requestId: " + wnr.requestId + ", caller: " + wnr.caller, GsonHelper.toJson(wnr));

备注:
SDK发奖流程的整个过程,都使用request_id将流程的日志串联起来,方便定位线上问题。

日志规则汇总##

  • 整个团队(包括运维人员)需要对日志级别有明确的规定,什么日志记入什么级别的日志,什么级别的错误出现要如何处理等
  • 需要定期对日志内容进行优化更新,目的就是通过日志快速准确的定位问题
  • 要明确不同日志的用途,对日志内容进行分类
  • 绝不要打印没有用的日志,防止无用日志淹没重要信息
  • 日志信息要准确全面,努力做到仅凭日志就可以定位问题
  • 要以同样严格的要求对待测试程序的日志
  • 日志的优化是一件持续不断需要投入精力的事,需要不断从错误中学习
  • 在RequestID中尽量编码更多的信息
  • 将一个请求的整个处理流程和唯一的requestID关联起来
  • 让一台机器开启DEBUG日志
  • 新上线服务器后一定要对日志进行观察,特别地,开发人员可以通过观察日志来确认新功能是否工作正常
  • 通过日志级别的提升来发现潜在问题
  • 对日志进行监控报警,比客户先发现系统问题
  • 通过日志中的关键字来确定系统的运行状态
  • 日志格式要统一规范
  • 将错误日志输出到一个单独的文件中进行分析
  • 要把日志的大小,如何切分,如何删除等作为规范建立起来

参考文献##

[1] ”Optimal Logging” Anthony Vallone from Google
http://googletesting.blogspot.jp/2013/06/optimal-logging.html

[2] 最佳日志实践
http://blog.jobbole.com/56574/

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 212,332评论 6 493
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 90,508评论 3 385
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 157,812评论 0 348
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 56,607评论 1 284
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 65,728评论 6 386
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 49,919评论 1 290
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,071评论 3 410
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 37,802评论 0 268
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,256评论 1 303
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,576评论 2 327
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,712评论 1 341
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,389评论 4 332
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,032评论 3 316
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,798评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,026评论 1 266
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 46,473评论 2 360
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 43,606评论 2 350

推荐阅读更多精彩内容