日志规范总结篇

什么是日志

日志用来记录用户操作、系统运行状态等,是一个系统的重要组成部分。然而,由于日志通常不属于系统的核心功能,所以常常不被团队成员所重视。对于一些简单的小程序,可能并不需要在如何记录日志的问题上花费太多精力。但是对于作为基础平台为很多产品提供服务的后端程序,就必须要考虑如何依靠良好的日志来保证系统可靠的运行了。

好的日志可以帮助系统的开发和运维人员:
1. 了解线上系统的运行状态
2. 快速准确定位线上问题
3. 发现系统瓶颈
4. 预警系统潜在风险
5. 挖掘产品最大价值

日志分类

诊断日志

  • 请求入口和出口
  • 外部服务调用和返回
  • 资源消耗操作:打开文件,IO等
  • 容错行为
  • 程序异常,Exception
  • 后台操作:多线程等
  • 关键程序的启动、关闭、配置加载

统计日志

  • 用户访问统计
  • 下单、支付日志

审计日志

  • 管理操作

日志中记录什么?

日志应该不多不少,能够从日志中得到所有需要的信息。在实践中经常发生日志不够的情况,例如:1)请求出错时不能通过日志直接来定位问题,而需要开发人员再临时增加日志并要求请求的发送者重新发送同样的请求才能定位问题;2)无法确定服务中的后台任务是否按照期望执行;3)无法确定服务的内存数据结构的状态;4)无法确定服务的异常处理逻辑(如重试)是否正确执行;5)无法确定服务启动时配置是否正确加载;
示例:
[INFO] RequestID:b1946ac92492d2347c6235b4d2611184, ErrorCode:1426, Message: callback request (to http://example.com/callback) failed due to socket timeout

容易遗漏的日志:

  1. 系统的配置参数:系统在启动过程中通常会首先读启动参数,可以在系统启动后将这些参数输出到日志中,方便确认系统是按照期望的参数启动的;
  2. 后台定期执行的任务:如定期更新缓存的任务,可以记录任务开始时间,任务结束时间,更新了多少条缓存配置等等,这样可以掌握定期执行的任务的状态;
  3. 异常处理逻辑:如对于分布式存储系统来说,当系统在一个存储节点上读数据失败时,需要去另一个数据节点上进行重试,可以将读数据失败这件事情记录下来,之后可以通过对日志的分析确认是否某些节点的磁盘可能存在故障。再比如,如果系统需要请求一个外部资源,可以将请求这个外部资源偶尔失败又重试成功这件事情记录下来,具体来说:
 
 
 
 
 
[INFO] RequestID:b1946ac92492d2347c6235b4d2611184, auth request (to http://auth1.example.com/v2) timeout ... 1 try    
[INFO] RequestID:b1946ac92492d2347c6235b4d2611184, auth request (to http://auth1.example.com/v2) timeout ... 2 try  
[INFO] RequestID:b1946ac92492d2347c6235b4d2611184, auth request (to http://auth1.example.com/v2) success
要好于:[INFO] RequestID:b1946ac92492d2347c6235b4d2611184, auth request (to http://auth1.example.com/v2) success
 
 

因为前者可以让我们预判被依赖的服务器服务质量有风险,也许需要进行扩容;日志中需要记录关键参数,出错时的关键原因等。


 
 
 
 
[INFO] RequestID:b1946ac92492d2347c6235b4d2611184, auth failed
[INFO] RequestID:b1946ac92492d2347c6235b4d2611185, content digest does not match
[INFO] RequestID:b1946ac92492d2347c6235b4d2611186, request ip not in whitelist
就不如:
[INFO] RequestID:b1946ac92492d2347c6235b4d2611184, auth failed due to token expiration
[INFO] RequestID:b1946ac92492d2347c6235b4d2611185, content digest does not match, expect 7b3f050bfa060b86ba781151c563c953, actual f60645e7107917250a6408f2f302d048
[INFO] RequestID:b1946ac92492d2347c6235b4d2611186, request ip(=202.17.34.1) 
 
 

日志级别

  • 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)日志来定位问题;

关于RequestId

一个系统通常通过RequestID来对请求进行唯一的标记,目的是可以通过RequestID将一个请求在系统中的执行过程串联起来。该RequestID通常会随着响应返回给调用者,如果调用出现问题,调用者也可以通过提供RequestID帮助服务提供者定位问题

RequestId的生成:

  • 简单系统,简单随机数即可
    RequestID = md5(time.Now() + random.Int())
  • 分布式环境需要建立全局唯一ID,参照twitter

慢操作日志

  • 服务在接收到一个请求的时候,记录请求的接收时间(T1),在请求处理完成待发送的时候,会记录请求发送时间(T2),通常一个请求的日志都记为INFO级别,然而当出现请求处理时间(T2-T1)超过一定时间(如10s)时,可以将该日志提升为WARN级别。通过该方法,可以预先发现系统可能存在的一些问题。
  • 同样的慢操作日志还可以用来记录系统一些外部依赖的处理时间,如一个服务可能依赖外部认证服务器来进行认证授权。通过记录每次认证请求的时间并将超出预期时间的请求日志采用WARN级别输出,可以尽早发现认证服务器是不是需要扩容等问题。
  • 慢日志的时间阈值应该是可以动态调整的,这样在进行系统优化时,可以将该报警时间阈值逐渐调小,不断地对系统进行优化
posted on 2018-06-25 11:16  飞翔的荷兰小猪  阅读(2036)  评论(0编辑  收藏  举报