没送到和没发生,不是一回事
一句话总结
日志为空时,区分“没送到”和“没有事情发生”的不是时间,而是发送方所附的序号。没有序号,丢失永远无法被证明;即使有序号,在重启面前也会说谎。
为什么需要它
看着采集器里积累的日志,说出“这 5 分钟内没有请求”的那一刻,我们就说出了自己无法证明的话。可能确实没有请求,也可能有请求,只是那一行在途中消失了。这两种情况的结论截然相反,却无法只靠文件区分。
RFC 5424 在第 8.5 节中把这一点写得非常清楚:syslog 协议没有保证送达的机制,底层传输(如 UDP)也不稳定,所以有些消息可能就这样消失了。而且同一节还补充了更令人不舒服的一点——可靠送达并不总是可取的。当接收方无法再接收时,发送方就必须被阻塞,而在 Unix 中 syslogd 是高优先级的系统进程,一旦它被阻塞,整个系统都会停下来。所以现实中的实现不是阻塞,而是有意丢弃,同时告知已经丢弃。这比不留任何痕迹地消失要好。
大小也是一个原因。同一份文档的第 6.1 节写道,传输接收方至少支持 480 个八位字节即可,超过 2048 个八位字节的消息可以被截断,也可以被丢弃。所以第 8.3 节建议把重要信息放在消息的前面,因为后面可能会被截掉。
工作原理
统计丢失的唯一方法,是发送方的单调递增序号。发送方附上 seq,并定期告知自己发到了哪里,那么只需用已接收序号的集合去减发送的范围,就能得出缺了什么。按区间归并来看就更有用——零星的一条条丢失,和 50 条成片缺失,原因是不同的。
但序号在重启时会回退。进程重新启动后,seq 又从 1 开始。所以只靠序号来判定同一行,会同时出现两种错误:重启前后的相同序号会被看成重复,而重启之后缺失的序号会被重启之前的记录遮住,看起来并没有丢失。解法只有一个——把序号和启动标识符(boot id)绑在一起。这也是 systemd 日志留下 _BOOT_ID 的原因。
同一行到达两次是正常的。没有收到响应的发送方会重新发送,于是接收方会收到同一行两次(at-least-once,至少一次)。这时需要的是“把什么视为同一行”的定义。如果有(主机、启动标识符、序号),那就是答案;如果没有,就只能用内容指纹,但这样一来,连真正完全相同的两个事件也会被折叠成一个。
接收的顺序不是发生的顺序。采集路径一旦拥堵,日志行要过几分钟才会到达。OpenTelemetry 日志数据模型之所以把时间字段分成两个,原因就在这里。Timestamp 是用原始时钟测得的事件发生时间,ObservedTimestamp 是采集端观测到该事件的时间。规范建议,在转换成只能容纳一个时间的格式时,“有 Timestamp 就用它,没有就用 ObservedTimestamp”。两者之差就是到达延迟,观察它的分布,就能看出采集路径的健康状况。
在现场相遇的样子
截止时间会改变数字。在午夜刚过时统计“昨天有多少个错误”,还没到达的日志行就会被漏掉。几天后再运行同样的查询,数字就增加了。这不是 bug,而是迟到。所以统计需要截止宽限(late window),这个宽限要看延迟分布的 p95 或 p99 来确定。
延长保留时间,也有永远不会到达的行。journald.conf(5) 中的 RateLimitIntervalSec= 和 RateLimitBurst= 规定,如果一个服务在规定区间内打印的条数超过规定数量,该区间内剩余的部分就会被丢弃。默认值是 30 秒 10000 条,按服务分别适用,并会留下一条告知丢弃数量的消息。日志因故障而暴增的那一刻,恰恰丢得最多。
丢失率因区间而异。整体 6% 这个数字通常没什么用。重要的是,在哪个 5 分钟里有 50 条整块缺失,以及这个区间是否与事故区间重合,这会改变结论。
下一项实验要做什么
同时做出采集器收到的文件和发送方的计数器,对两者进行比较来统计丢失。把缺失的序号按区间归并,折叠 at-least-once 造成的重复,求出到达延迟的分布。接着计算如果在截止时间统计会漏掉多少条,最后用数字展示,在因重启而序号回退的主机上,如果忽略启动标识符,丢失和重复会怎样互相颠倒。