应用程序日志规范

Question

来自应用层的日志是你的应用对你唯一的反馈。让日志合理化并具有良好的检索能力，就像在一个黑暗的房间里点亮了一个火把。当任何问题出现时，“充分利用日志”这一做法带来的效果常常被我们低估。作为软件工程师，我们能利用应用层日志解决问题，以及了解应用整体的健康状况。

日志还可以帮助分析应用程序的性能。

目录

什么是日志

时间戳(timestamp) + 数据(data) = 日志(log)

• 已发生事件的历史记录
• 按事件顺序记录系统的事件和状态
• 记录系统/网络的活动
• 为审计提供依据（who done what, where, when and why (5W)

log 单词的愿意是“原木，航海日志”

古代的航海家经常把非常结实的原木做成桅杆，而最古老的记事工具根本不是纸笔等，如何记事呢？ 很简单，太阳东升西落一次，航海家就在桅杆上刻下一个刻痕，代表一天已经过去了，于是 log 就从“原木”演化到“航海日志”。

日志记录什么

记录有帮助的信息

• 找到已发生事件的任何信息 When What Where How Who
• 理清简洁的上下文相关信息
• 分析各种可能性
• 人工、半自动、自动
• 远程可下载的日志文件
• 导致系统缓慢的蛛丝马迹
• 认证/授权信息

什么时候记录日志

• 操作日志

  • 出现影响单个用户的错误时
  • 出现影响所有用户的关键条件时
  • 系统/应用程序的启动、停止、重启时
  • 运行中活动导致的属性改变
  • 新组件、插件的安装
  • 配置发生变更
  • 代码/缓存变更
  • 开始备份
  • 日志访问审计

• 安全相关日志

  • 登入/登出(本地和远程)
  • 密码变更/授权变更
  • 失败的资源访问（拒绝的授权）
  • 特权账号的所有活动

• 监管/标准要强制（外部系统访问）

  • SOX (访问财务系统)
  • PCI (Cardholder data access)
  • etc.

• 业务相关日志

日志消息分解

上下文(Context)	意思(Meaning)
When	Timestamp
Where	System/Application/Component
Who	User
What	Action
Result	Status
Priority	Serverity, rank, level

记录的一行日志，就像讲述一个故事，when, what, who, and why

日志行结构化标准

在日志行中固定使用一个结构，拥有这些简单的结构化后，日志信息就会变得易于检索。非常推荐在日志行中记录上下文信息，例如：当记录订单无法正常发货的日志时，可以同时添加订单的详细信息到日志中（当然是指订单中不敏感的信息）。

1. 每行日志遵从标准日志行结构化样例
2. 多行日志，第2行开始，以一个空白字符开头
3. 日志详情中，如果继续需要结构化支持，建议在前面使用 key1:value1 key2:value2的形式，如果value包含有非字母数字部分，则使用双引号包含

标准日志行结构化样例

2020-04-23 20:50:06.392    INFO 66668 --- [1] [127.0.0.1-1544498251.152-3835-1940] logger.go:145        : {"key1":"value10","key2":"value20"} read ~/.otterbeat/TableStats.lastTime got no new items

它包含以下结构化部分，每个部分以一个空格分开：

Part1	Part2	Part3	---	Part4	Part5	Part6	:	Part7	Part8
时间	日志级别	PID	---	[线程ID]	[TRACEID]	打印位置	:	上下文	日志详情

1. 时间，固定格式 yyyy-MM-dd HH:mm:ss.SSS
2. 日志级别，占位 7，右对齐，大写。取值 ERROR WARN/WARNING INFO DEBUG
3. 线程ID，或者协程ID
4. TRACEID，跟踪ID
5. 打印位置，格式 logger:line GO语言 %-20s JAVA %-40s
6. 上下文，使用 JSON 格式数据，可选，当存在时写入，以便日志解析器解析
7. 日志详情

多行日志示例

2020-04-27 17:39:04.070 WARNING 71370 --- [19] [] log_test.go:30       : errors error
 github.com/bingoohuang/gou/lo.TestSetupLog
 	/Users/bingoobjca/github/gou/lo/log_test.go:26
 testing.tRunner
 	/usr/local/go/src/testing/testing.go:991
 runtime.goexit
 	/usr/local/go/src/runtime/asm_amd64.s:1373
 open failed
 github.com/bingoohuang/gou/lo.TestSetupLog
 	/Users/bingoobjca/github/gou/lo/log_test.go:27
 testing.tRunner
 	/usr/local/go/src/testing/testing.go:991
 runtime.goexit
 	/usr/local/go/src/runtime/asm_amd64.s:1373
 read config failed
 github.com/bingoohuang/gou/lo.TestSetupLog
 	/Users/bingoobjca/github/gou/lo/log_test.go:28
 testing.tRunner
 	/usr/local/go/src/testing/testing.go:991
 runtime.goexit
 	/usr/local/go/src/runtime/asm_amd64.s:1373
2020-04-27 17:39:04.070    INFO 71370 --- [19] [] log_test.go:33       : {"key1":"value10","key2":"value\n20"} abcefg

日志文件

1. 日志默认存储在 $HOME/logs/{appName}/目录下面，例如：/Users/bingoobjca/logs/otterbeat/
2. 当前正在写入的日志名为 {appName}.log，不带日期后缀，例如：otterbeat.log
3. 归档日志，以天为单位，格式为 {appName}.log.{YYYY-MM-DD}，日期作为文件名后缀，例如：otterbeat.log.2020-04-24
4. 归档日志的默认保留时间是7天

应用程序

1. 禁止：禁止日志中写入大量的噪音信息，比如 ====，$$$$ 等
2. 禁止：标准日志中已经输出当天时间，应用程序，应避免重复输出
3. 禁止：标准日志中输出的其它内容（进程号/线程号)等，应用程序也应该避免重复输出

选择日志库

开源的日志库非常多，基本每个语言都有数十种，选择一个符合公司/业务需求的日志库需要精挑细选，有一个简单的指导原则是尽可能使用比较流行的日志库的稳定版本，入坑的几率要小一点。例如：

• Java 使用 Log4J、LogBack。
• Golang 使用 logrus、go-kit。
• Python 默认集成的日志库大部分场景都够用，建议阅读一下 CookBook。
• C++ 推荐使用 spdlog，高性能、跨平台。

日志形态选择

• 在虚拟机/物理机的场景中，绝大部分应用都以文件的形式输出日志（只有一些系统应用输出到 syslog/journal）；

• 在容器场景中，多了一个标准输出的方式，应用把日志打到 stdout 或 stderr 上，日志会自动进入到 docker 的日志模块，可以通过 docker logs 或 kubectl logs 直接查看。

  容器的标准输出只适应于比较单一的应用，例如 K8s 中的一些系统组件，线上的服务类应用通常都会涉及到多个层级（中间件）、和各种服务交互，一般日志都会分为好几类，如果全部打印到容器的标准输出，很难区分处理。

  同时容器标准输出对于 DockerEngine 的性能消耗特别大，实测 10W/s 的日志量会额外占用 DockerEngine 1个核心的 CPU（单核 100%）。

日志级别

日志等级是用来区分日志对应事件严重程度的说明，这是所有日志中必须具备的一个选项。通常日志会分为6个不同的等级：

1. FATAL（致命）：用来输出非常严重或预期中不会发生的错误。
   • 遇到此种错误应当立即报警并人工介入处理，应用程序可以选择 自杀。
   • FATAL类型日志一定是非常严重的错误、需要人工处理的场景打印的
   • 比如，系统缺少UTF8编码支持，内存/磁盘空间不足等
2. ERROR （错误）：非预期中的错误，此种错误可能导致部分系统异常但不会影响核心业务和系统正常运行。
3. WARN（警告）：潜在的危险或值得关注的信息（比较核心的路径）。
   • ERROR和WARNING的区别很多程序员难以选择，可以从告警角度考虑：ERROR 一般需要告警，WARNING 不需要。
4. INFO（信息）：应用执行过程中的详细信息，一般通过该信息可以看到每个请求的主要执行过程。
   • 通常线上只能打开INFO或WARN的日志。
5. DEBUG（调试）：用于线下调试的日志信息，用于分析应用执行逻辑，线上应用切勿开启。
   • DEBUG 日志可以多打，方便分析问题，特别是 新鲜出炉 的代码，可能出现问题的地方特别多，DEBUG 日志多打时，比较方便分析问题。
6. TRACE（跟踪）：输出最细致的运行轨迹，可能包含涉及的数据内容。

最佳实践

1. 所有用户请求日志，必须记录。
2. 易于搜索的日志输出方式
   正例：没有新的数据时，在详细日志中打印 没有新的数据，有输出时打印 发现新的数据，共10条
   反例：只是在详细日志中打印 发现0条新数据，或者 发现10条新数据，这样难于搜索 发现新数据
3. 不好的例子
   • 记录没有任何细节
   • 没有上下文信息
   • 不一致的格式
   • 日志信息不相关联
   • 主观/解释性消息
   • 太多无用的日志记录
   • 记录到单个超大文件
4. 好的例子
   • 可能“多变”或者“耗时”的地方记录日志
   • 记录正常控制之外访问（数据库，远程API等）
   • 记录超出预期的性能事件（慢查询等）
5. 合理地记录信息
   • 过多的信息会干扰我们的视听，而信息太少又不足以满足我们的需求
   • 记录多少的日志信息才最为合理，这很难把握平衡，对我们而言这也是个挑战
   • 在微服务的场景中，例如使用唯一的请求标识符(TraceID)来标记请求，以便进行服务之间请求的追踪
   • 我们需要记住的另一件事是：日志是暂存的事物，而非永久存在的。因为它们没有被存储在数据库中，往往只存在几天到几周的时间
6. 始终遵循严格的日志级别
   • 如果线上出现 emergency 级别日志，这意味着你的待命电话将在凌晨 2 点响起
   • 如果出现的仅仅是 info 级别的日志，这不需要打扰到任何人
   • 你和你的团队需要制定并同意一些日志设定标准
   • 程序中的日志库需要具备运行期间变更日志等级的能力，方便在遇到问题需要分析时临时更改日志等级。
   • 通常在新功能上线，涉及的日志可适当提升一个等级，方便实时观察和监控，待稳定后再调整到正常（记得加上注释，方便改回来）。
7. 小心地记录日志（不要影响系统性能）
   • 确保添加日志后不会让程序的返回时间增加过多的毫秒数
   • 尽可能地用异步方式记录日志，日志甚至能直接写入本地日志文件或使用日志传输工具传输至你所选择的日志服务
   • 也可以使用基于语言/框架开发的久经考验的库
   • 使用队列也可以作为记录日志的选项，但请记住，在查看日志时可能存在延迟

语言定制

Golang

1. 使用 github.com/pkg/errors 库的 errors.Wrapf(err, "open file %s", filename) 来形成错误堆栈
2. 使用 %+v 来打印日志堆栈 logrus.Warnf("errors %+v", err)

参考资料

1. Logging best practices 有人翻译 日志记录的最佳实践 logging-best-practices.pdf
2. Are logs a software engineer’s best friend? Yes -- follow these best practices local pdf
3. Kubernetes 中日志的正确输出姿势