shoulder-specs-doc/src/main/asciidoc/specs/base/log.adoc

// tag::main[]

== 术语定义：
* 日志
** 运行日志/系统日志
*** 开发人员为了方便定位错误而打的日志，该部分较为自由
** 追踪日志/调用链日志
*** 分布式系统中为了追踪某个调用链流程相关的日志，该部分一般遵循一定的规范如 https://opentracing.io/docs/overview/[OpenTracing]。
** 特殊日志
*** 面向某特定领域，具有统一格式约束的日志，以在特定场景实现某一功能的日志。如操作日志/业务日志、审计日志。如：操作日志统一使用 `JSON` 格式，并且要求包含指定的字段。
* 级别
** 用于日志分类：描述日志重要程度、统一处理某一级别的日志（如控制输出路径、文件名、保存时间、是否输出等）。
* 日志服务
** 拥有处理日志的能力的软件系统，通常具有采集、存储、检索、分析日志的能力，典型如 `ELK`。

== 规范约束

=== 日志文件规范

==== 日志文件输出目录
* 每种程序日志必须统一路径，通常以软件标识命名目录，如 `order` 服务的所有日志输出到 `xxx/order` 文件夹下
* 一个的软件系统下的不同程序统一输出到特定目录，如 `/logs/shoulder/`

==== 日志文件存留时间、切分、压缩
* 该部分按照软件定义和日志级别来确定，如每天的日志压缩一次，最多保留十天或总大小最大允许200M。

==== 日志文件命名
* 按照日志级别区分，如包含 debug、error、other、dts 日志文件
** debug 包含 debug 级别及以上的日志
** error 包含 error 级别及以上的日志
** other 非本软件代码打印的日志
** dts 分布式链路追踪日志，而非单指 trace 级别
* 当前日志文件命名
** `软件标识.日志级别.log`，如 `xxx.debug.20200101.log`
* 压缩日志文件命名（历史日志文件）
** `软件标识.日志级别.日期.log`，如 `xxx.debug.20200101.log.zip`

=== 通用日志输出格式规范

[TIP]
====
定义统一的日志格式可以统一进行日志分析，下举例统一格式
====

[TIP]
====
对日志做格式的目的是能够方便的追溯与排查问题，
====

```text
日志时间SP日志级别SP程序标识SP[代码位置]SP[线程标识]SP<调用链标识>SP[错误码]SP-SP日志输出正文
```

==== 格式说明

* SP
** 表示一个空格。
* []、<>
** 表示内容可选，并且需要输出到对应括号内，如果没有则使用字符 `-` 代替之。

* 基本值特殊字符约束
** 除了开发者在代码中写的 `日志输出` 不允许有 `空格` 、 `[` 、 `]` 、 `<` 、 `>`

* 日志时间
** 日志产生的时间，能够方便的追溯与排查问题。
** 示例
*** 带时区 `2020-01-01T00:00:00.000+08:00`、`2020-01-01T00:00:00.000Z`。
*** 不带时区 `2020-01-01 00:00:00.000`。
* 日志级别
** 包含 6 个级别（`TRACE`、`DEBUG`、`INFO`、`WARN`、`ERROR`、`FATAL`）
** [.line-through]统一按5个字符长度输出，以保持一致

* 程序标识
** 输出日志的代码所属程序标识，可为模块名称也可为服务名，目的便于区分哪里产生的，与类名、方法名组合定位到具体代码。
** 示例
*** `spring-aop`、`spring-boot-redis`、`shoulder-core`、`shoulder-crypto`

* 代码位置
** 打印日志的代码位置，具体可为代码文件路径，类路径、方法名、代码行号等。

* 线程标识
** 由于获取堆栈信息较耗费性能，一般不打印该值，使用 `-` 来代替，但有时为了方便追踪，需要加上该内容，一般为线程名称/ID。

* 调用链标识
** 即 `traceId` ，用于快速定位一次调用链，没有则使用 `-` 来代替。

* 错误码
** 记录错误日志时（WARN 级别及以上），需要同时记录错误码，以 `0x` 开头，十六进制格式输出。没有则使用 `-` 来代替。

* 日志输出正文
** 开发人员自定义的日志内容，推荐使用英文（优化压缩率、避免乱码、避免歧义）；记录参数时推荐使用 `[param1=value1,param2=value2..]其他内容` 这种形式。


=== 日志级别规范

* 完整调用信息约束
** 记录 WARN 级别及以上的日志时，需要记录触发端点（接口地址、定时任务标识、消息事件类型）参数、触发用户标识、若存在异常则需要包含调用栈信息，以便排查、复现问题。

* TRACE
** 一般不记录参数、变量值，仅用于调试、测试期间标记记录程序执行到此，在其他级别日志记录未开发或缺失时来判断程序是否执行至此，程序正常运行时一般不打印该级别日志。
** 举例：发起远程调用、完成远程调用、收到调用请求、完成调用请求、方法开始前、方法完成后。
* DEBUG
** 记录出入参数值、关键变量值、接口响应值等。
* INFO
** 程序自身状态变更、配置参数值变更、意料之中的异常、定时任务、通知变更、API接口被调用、特殊数据的初始化、关键的数据变更等，一般用于调试、测试期间以及复现问题时打印。
* WARN
** 程序抛异常，导致一次功能失效，且容忍这类错误，设计了人性化的提示，单次发生不影响再次操作、后续流程、其他操作、其他用户。
** 举例：程序启动无法读取到配置文件而使用默认值；调用其他服务接口失败且有不影响业务的容错处理；超出了需求范围&&可以放弃的业务:程序性能达到上限无法继续处理新的请求/识别出是爬虫；意料之中的特定异常(如由客户端传入参数有误引起的)。
* ERROR
** 程序触发意料之外的异常、状态，导致业务失败，可能导致后续相同功能失败或影响其他功能，程序无法自身解决该类问题，需要产生告警，告知维护人员解决该问题，常常是软件依赖的其他软件或基础设施不正常。
** 举例：关键业务（功能、定时任务、通知处理）失败；出现程序功能部分不可用（关键配置项缺少、关键中间件连接失败、系统内存、硬盘等上限）。
* FATAL
** 程序崩溃，接近所有功能不能使用，后续操作无法进行，必须重启或由专人来排查，发生概率极低。
** 举例：程序所占有资源被其他软件或工具篡改而导致的系统无法按照软件的指令继续执行（检测到非法外挂）、文件损坏无法启动；



// end::main[]


// tag::dts[]
== 追踪日志

记录远程调用和内部调用的日志，用于追踪业务流向，将一次业务流程在不同服务/系统中产生的系统日志相关联，为排查问题提供方便。

=== 内容要求

该部分一般使用第三方等成熟的开源方案快速落地，如 Zipkin、SkyWalking、Cat 等。

[cols="1,4"]
.字段与要求
|===
| 字段名	 | 含义

| *node_id*	 | 节点编号，*必填*。格式：`<应用标识>.@<IP>`。
| *trace_id* | 用于标识一笔业务的唯一序号，*必填*。由 `0~9`、`a~z` 和 `A~Z` 构成，长度 `32` 字符。
| *span_id*	 | 用于标识某一阶段调用序号，*必填*。由 `0~9` 、 `a~z` 和 `A~Z` 构成，长度 `32` 字符。
| parent_id	 | 用于标识某一阶段的父调用序号，格式同 `span_id`，选填。
| *action*	 | 用于记录若干和调用轨迹有关的特定动作。动作是一个枚举列表，*必填*。
| span_name	 | 被调用的方法名称或接口名称，选填，当 `action` 字段值为 `client send`，`server receive`，`invoke` 时必填。
| notation	 | 当action 表示为错误返回时，用来携带错误信息，选填。允许有换行和空格，长度不超过 `200` 字符，采用 `UTF-8无BOM` 格式编码。
| code	 | 用来携带错误码，选填。
|===

=== 记录时刻

[cols="2,1,2"]
.记录时刻
|===
| 使用场景	 | action	 | 备注

| 业务发起方远程调用开始，产生trace id	 | trace start	 |
| 业务发起方远程调用结束	 | trace end	 | 配对trace start使用
| 请求端调用rpc前，发送网络请求	 | client send	 |
| 请求端收到正常响应或者调用失败	 | client receive	 | 配对client send使用
| 服务端接收到请求报文	 | server receive	 |
| 服务端完成请求处理，发送响应	 | server send	 | 配对server receive使用
| 方法开始调用	 | invoke	 |
| 方法完成	 | return	 | 配对invoke使用
|===

==== HTTP 传输要求

在HTTP请求中需要传递追踪上下文信息，把追踪字段添加至请求头 `Header`

* trace_id：同表2中的 `trace_id` 字段
* span_id： 同表2中的 `span_id` 字段

// end::dts[]


// tag::op[]

== 操作日志

=== 记录目的

给使用软件的管理员看的，方便快速了解系统因 `哪个用户` 在 `什么时刻` 用 `哪个终端` 的 `什么操作` ，操作了 `什么类型` 的 `哪个对象` ， `操作结果` 如何， `操作详情` 是怎样的， `关联的上下文` 是什么。

[INFO]
====
https://oss.sonatype.org[sonatype] 网站就是一个例子，简单的展示了上述的内容。
====

=== 内容要求

有的系统将日志直接放进数据库，故须要有一定的长度限制，下表中列出了推荐最大长度，实际中可以灵活调整，也有的系统选择放入 `ES` 中，长度限制就显得没那么大必要了。

[cols="2,1,1,8"]
.操作日志格式
|===
| 字段名称 | 长度 | 必填 | 说明

4.+^.^| *操作者相关信息*
| *userId*	 | 128	 | 是 | 用户标识（如用户名、userId）；为系统内部操作时（如定时任务、接收消息通知），填写执行操作的服务实例名，格式为 `system.应用标识.实例标识`
| userName	 | 128	 | 否 | 用户昵称
| personId	 | 64	 | 否 | 用户对应人员标识
| userOrgId	 | 128	 | 否 | 用户所属 `用户组` 或 `群组` 或 `部门` 的编号。
| userOrgName    | 255   | 否   | 用户组名称。
| *terminalType* | 1 | 是 | 操作者所使用终端的类别 `0` 表示 `系统内部`、`1` 表示 `浏览器`、`2` 表示 `APP`、`3` 表示 `PC客户端`
| ip	 | 255	 | 否 | 操作者所在机器 `IP`；系统内部操作时，填写服务所在机器 `IP`。
| terminalId	 | 128	 | 否 | 操作者所使用终端的唯一标识：如 `MAC` 地址。
| terminalInfo	 | 256	 | 否 | 操作者所使用终端详情信息，如浏览器中的 `UserAgent`。
4.+^.^| *操作动作相关信息*
| *operation*	 | 255	 | 是 | 操作动作标识。
| *operationTime*	 | 128	 | 是 | 操作时间，格式为 `年-月-日T时:分:秒.毫秒时区`，如 `2017-09-20T13:42:38.349+08:00`。
| params	 | - | 否 | 操作对应业务方法/接口的入参，一般关键/特殊业务才会使用。`JSON` 形式，见下方 `操作日志参数格式`
| *result*	 | 1 | 是 | 业务操作结果：`0` 表示 `成功`、`正确`、`1` 表示 `失败`、`不正确`、`2` 表示 `部分成功`
| errorCode	 | 32	 | 否 | 当操作结果为失败时，记录操作失败对应的错误码。
| detailKey	 | 128	 | 否 | 操作详情（ *支持* 多语言时填写），多语言 key 格式：`op.detail.<操作内容标识>`，支持占位符，采用 `%1`, `%2`, `%n` 形式，n表示第n个参数；不支持多语言时留空。
| detailItems | - | 否 | 操作详情占位参数（ *支持* 多语言时填写），用于填充 `detailKey` 的占位符。
| detail	 | 4096	 | 否 | 操作详情（ *不支持* 多语言时填写）详细的描述用户的操作内容，也可填写被操作对象的 `JSON` 字符串。
4.+^.^| *被操作对象相关信息*
| objectType	 | 128	 | 否 | 操作对象的类型标识。
| objectId	 | 128	 | 否 | 操作对象的标识，若存在多个值时， 以 `,` 分隔，如 `[1,2,3,4,5]`。
| objectName	 | 255	 | 否 | 操作对象的名称，若存在多个值时，以 `,` 分隔，如 `[角色1、角色2]`。
4.+^.^| *其他信息*
| businessId	 | 128	 | 否 | 存放与本次操作所关联其他业务操作的业务号。用于多个请求完共同完成一个业务功能时。如：上传csv进行数据的批量导入场景：上传导入文件、校验导入数据、点击确认导入、导入成功业务相关可以填同一个标识符
| *appId*	 | 128	 | 是 | 服务唯一标识。
| traceId	 | 128	 | 否 | 调用链标识。
| 自定义扩展字段	 | -	 | 否 | 扩展字段，用于个别服务需要，一般留空。
|===

与例子中的 https://oss.sonatype.org[sonatype] 网站类比，一个业务是由多个子业务构成的，他们有共同的 `businessId`，每个业务/动作/操作都有唯一标识 `operation` / `typeId`，记录了操作的内容（被操作对象），操作结果如何，错误信息是什么，操作详情等。
可以看到自己最近什么时间在哪种终端做了什么。


[cols="2,1,1,4"]
.操作日志参数格式
|===
| 字段名称 | 长度 | 必填 | 说明

| name	 | 128	 | 是 | 参数名称
| value	 | 64	 | 是 | 参数值
| supportI18n | 1 | 是 | value 字段是否支持多语言
|===


<!-- | type   | 64	 | 是 | value 类型： `text` 普通文本，不支持多语言； `i18n` 支持多语言； `url` 链接； -->

=== 使用场景

* 业务操作，使数据库数据发生变化时（增删改）
* 重要数据的读取时
* 定时任务、补偿任务时

=== 编码建议

* 方法抛出异常，日志框架默认会将执行结果置为失败，并尝试记录操作日志
* 有的系统自己探索日志可视化方案，为了使得操作日志支持多种语言同时查看，推荐将以下标识性字段进行一定的多语言处理。
其中部分字段为翻译型，可以自定义 `多语言key前缀` 以便于解析翻译，也可以直接尝试翻译，翻译失败则展示原值。

[cols="1,1,4"]
.多语言字段对照表
|===
| 字段名称 | 说明 | 建议方案

| operation	 | 操作动作标识 | 支持多语言时添加特定前缀，如 `op.op.<操作动作标识>`
| objectType | 被操作对象类型 | 支持多语言时添加特定前缀，如 `op.objType.<操作对象类型标识>`
| detail	 | 操作详情 | 使用 `detailKey` 作为多语言key，格式：`op.detail.<操作内容标识>`，detailItem 填充占位符
| terminalType | 终端类型 | 采用枚举/数据字典，展示层翻译
| result	 | 操作结果 | 采用枚举/数据字典，展示层翻译
| appId	 | 应用标识 | 结合基本规范，采用数据字典，展示层翻译
| errorCode	 | 错误码 | 结合错误码规范，给出错误原因和排查建议
| operationTime | 操作时间 | 结合国际化规范，时间格式可改变
|===


== 日志审计

审计目的：提前发现风险，保证重要数据不被丢失，分析风险行为。如恶意攻击、非法爬虫、越权访问、潜在漏洞、命令审计、账户行为（改密）审计、登录（登录地点）审计、重要资源访问审计等。

[NOTE]
====
异常日志告警一般放在错误码监控上，不在审计中，另外，审计一般不是实时的。
====

=== 审计流程 footnote:[日志审计, https://www.freebuf.com/articles/web/96675.html]

. 定义特征
** 定义行为特征，如SQL注入测试、端口扫描等
. 读取
** 从日志存储中进行日志读取，由于数量大，故进行流式读取。
. 匹配与分发
** 通过多个过滤器进行匹配，如果匹配则将结果分发至对应处理器继续处理
. 结果处理
** 根据符合的结果进行一定的处理，如筛选出频率最高的 `IP` 进行封禁，当频次超过某个阈值或发送某个不应该发送的动作则进行 *报警* ，产生处理情况报表。

== 编码和使用

* debug环境下，nginx 日志中加入上游服务器的地址更容易调试，`nginx.conf` 中加入 `add_header X-UpStream $upstream_addr;`
* 合理利用日志框架的 `MDC` 机制，利用该能力将一些通用的数据记录其中，简化代码
* 以下情况必须打印日志
** 数据变更时（增、删、*改*），`debug`
** 条件分支时， `debug`
** 数据量异常时（过大、过小） `info` / `warn`


// end::op[]