打开调试日志那天,排查需要的那几行反而没了
目标
用一个固定的日志文件制作按级别划分的成本表,亲手实现按请求采样、保留错误、折叠重复和每秒上限,把成本与可调查性之间的权衡变成数字,再用策略文件固定下来。
为什么重要
降低日志成本的要求总会到来。这时最简单的答案是“提高级别”和“做采样”,但两者只要做错,就只是成本降了,调查能力却归零。因为人在调查时读取的单位不是行,而是一个请求留下的一组行。如果按行保留 10%,没有一个请求能从头读到尾,而如果按请求保留 10%,那 10% 就是完整的。再加上“以错误结束的请求不剔除”这一条规则,成本几乎不变,失败请求的保留率却会从 0% 提高到 100%。本实验制作的表,可以直接作为下次成本会议上的依据。
步骤
- 材料日志是
/opt/lab/logsample/app.log。行格式是<시각> <수준> req=<id> handler=<경로> msg="<메시지>"(占位符依次为时间、级别、ID、路径、消息),级别有 DEBUG、INFO、WARN、ERROR 四种。在/root/obs-log-sampling/cost.tsv中写四行,没有表头,每行是以制表符分隔的三个字段<수준> <줄 수> <바이트>(占位符依次为级别、行数、字节数)。字节数是该级别的各行所占的字节数,并且包含一个换行符。 - 把丢弃全部 DEBUG 行后的结果,用六行写入
/root/obs-log-sampling/drop-debug.txt。分别是kept_lines=<남은 줄 수>(占位符为剩余行数)、kept_bytes=<남은 바이트>(占位符为剩余字节数)、saved_pct=<바이트 기준 절감률, 소수 두 자리>(占位符为按字节计算的节省率,保留两位小数)、req=<오류로 끝난 요청 중 request_id 가 사전순으로 가장 앞선 것>(占位符为以错误结束的请求中 request_id 按字典序最靠前的那一个)、req_lines_before=<그 요청의 원래 줄 수>(占位符为该请求原来的行数)、req_lines_after=<DEBUG 를 뺀 뒤 그 요청에 남은 줄 수>(占位符为去掉 DEBUG 之后该请求剩余的行数)。“以错误结束的请求”是至少有一行级别为 ERROR 的请求。 - 创建
/root/obs-log-sampling/sample.py。以python3 sample.py --rate N < 입력 > 출력(占位符依次为输入、输出)调用时,读取标准输入的行,只把要保留的行原样写到标准输出(保持输入顺序)。保留的标准是按请求——设行中的req=值为r,如果int(hashlib.md5(r.encode()).hexdigest()[:8], 16) % N == 0,就保留该行。--rate 1会全部保留。然后用python3 sample.py --rate 10 < /opt/lab/logsample/app.log > /root/obs-log-sampling/sampled-10.log生成结果文件。 - 给
/root/obs-log-sampling/sample.py增加--keep-errors选项。有这个选项时,只要有一行级别为 ERROR 的请求,无论采样率是多少,都保留它的所有行(保持输入顺序)。没有该选项时的行为必须与第 3 步相同。然后用python3 sample.py --rate 10 --keep-errors < /opt/lab/logsample/app.log > /root/obs-log-sampling/sampled-10-err.log生成结果。 - 把采样率
N依次改为 1、4、10、50,制作/root/obs-log-sampling/tradeoff.tsv。没有表头,共四行,每行是以制表符分隔的五个字段<N> <표본만 썼을 때 남은 줄 수> <그때 완전히 남은 오류 요청 수> <오류 보존까지 켰을 때 남은 줄 수> <그때 완전히 남은 오류 요청 수>(占位符依次为 N、仅用采样时剩余的行数、此时完整保留的错误请求数、同时启用错误保留时剩余的行数、此时完整保留的错误请求数)。“完整保留的错误请求”统计的是在以错误结束的请求中,结果文件里至少还剩一行的请求。 - 创建
/root/obs-log-sampling/squeeze.py。以python3 squeeze.py [--max-debug-per-sec K] < 입력 > 출력(占位符依次为输入、输出;K 的默认值为 20)调用时,依次应用两条规则。① 如果与前一行的(级别、handler、msg)完全相同,就视为一组,只保留第一行,但如果该组的行数 k 大于等于 2,就在该行末尾附加repeated=<k>。② 折叠之后,只对 DEBUG 行,在同一秒内(时间字符串的前 19 个字符)从前往后只保留 K 行,其余丢弃。然后生成python3 squeeze.py < /opt/lab/logsample/app.log > /root/obs-log-sampling/squeezed.log,并在/root/obs-log-sampling/squeeze.txt中写四行in_lines=、after_collapse=、after_cap=、bytes_saved_pct=<소수 두 자리>(占位符为保留两位小数的值)。 - 把
sample.py --rate 10 --keep-errors的输出直接交给squeeze.py(默认上限),生成/root/obs-log-sampling/final.log。然后在/root/obs-log-sampling/final.txt中写八行——in_lines=、out_lines=、in_bytes=、out_bytes=、reduction_pct=<바이트 기준, 소수 두 자리>(占位符为按字节计算、保留两位小数的值)、error_requests_kept=<final.log 에 줄이 남아 있는 오류 요청 수>(占位符为 final.log 中仍有行的错误请求数)、trace_req=<2단계에서 고른 그 요청 id>(占位符为第 2 步所选的那个请求的 ID)、trace_lines=<final.log 에 남은 그 요청의 줄 수>(占位符为 final.log 中剩余的该请求的行数)。 - 用 YAML 写
/root/obs-log-sampling/policy.yml。在levels之下,为 DEBUG、INFO、WARN、ERROR 四个级别各设置retain_days(整数)和sample_rate(整数)。ERROR 的sample_rate必须是 1,retain_days必须大于 DEBUG。DEBUG 的sample_rate必须大于等于 2。在rules之下放keep_errors_whole_request: true、collapse_repeats: true、max_debug_per_sec(第 6 步使用的默认值)。在estimate之下,把raw_bytes、kept_bytes、reduction_pct写成与第 7 步结果相同的值,最后用note以不少于 40 个字符的一句话写出这个策略的权衡。
参考
- 工作目录是
/root/obs-log-sampling。如果不存在,请先创建。 - 材料日志是
/opt/lab/logsample/app.log(约 8,280 行 · 795KiB)。这是固定的文件,所以运行多少次,得到的答案都一样。生成它的方法在同一目录的gen_log.py中。 - 行格式是
<시각> <수준> req=<id> handler=<경로> msg="<메시지>"(占位符依次为时间、级别、ID、路径、消息),以空格分隔的第二个字段是级别。 - 过滤器请做成读取标准输入、写入标准输出的程序——这样才能用管道串联起来。
- 不要启动 Loki。本实验处理的是在放入存储之前,由应用发出的行本身的挑选。
- 常见错误:按行号抽样。一个请求被拦腰截断,什么也无法重建。
- 常见错误:不分级别地设置每秒上限。在暴增的那一刻 ERROR 会被截掉。
- Logs (OpenTelemetry)、Logs Data Model (OTel 规范)、hashlib (Python 标准库)、Effective Troubleshooting (SRE Book 第 12 章)、Monitoring (SRE Workbook 第 4 章)
先统计各级别各花了多少
材料日志是 /opt/lab/logsample/app.log。行格式是 <시각> <수준> req=<id> handler=<경로> msg="<메시지>"(占位符依次为时间、级别、ID、路径、消息),级别有 DEBUG、INFO、WARN、ERROR 四种。在 /root/obs-log-sampling/cost.tsv 中写四行,没有表头,每行是以制表符分隔的三个字段 <수준> <줄 수> <바이트>(占位符依次为级别、行数、字节数)。字节数是该级别的各行所占的字节数,并且包含一个换行符。
级别是以空格分隔的第二个字段。可以用 awk '{print $2}' 取出。字节数可以像 awk '{n[$2]++; b[$2]+=length($0)+1}' 这样,把行长度加 1 后累加。这四个数字的比例就是本实验的出发点——看看哪个级别占了体积的大部分。
关掉 DEBUG 之后,留下什么、消失什么
把丢弃全部 DEBUG 行后的结果,用六行写入 /root/obs-log-sampling/drop-debug.txt。分别是 kept_lines=<남은 줄 수>(占位符为剩余行数)、kept_bytes=<남은 바이트>(占位符为剩余字节数)、saved_pct=<바이트 기준 절감률, 소수 두 자리>(占位符为按字节计算的节省率,保留两位小数)、req=<오류로 끝난 요청 중 request_id 가 사전순으로 가장 앞선 것>(占位符为以错误结束的请求中 request_id 按字典序最靠前的那一个)、req_lines_before=<그 요청의 원래 줄 수>(占位符为该请求原来的行数)、req_lines_after=<DEBUG 를 뺀 뒤 그 요청에 남은 줄 수>(占位符为去掉 DEBUG 之后该请求剩余的行数)。“以错误结束的请求”是至少有一行级别为 ERROR 的请求。
按字典序最靠前的 ID,可以用 grep ' ERROR ' | grep -o 'req=[0-9a-f]*' | sort -u | head -1 找到。想只看那个请求的行,用 grep 'req=<id>' 即可。这一步的问题不是剩下多少行,而是能不能读懂那个请求的流程。
按请求而不是按行来抽样
创建 /root/obs-log-sampling/sample.py。以 python3 sample.py --rate N < 입력 > 출력(占位符依次为输入、输出)调用时,读取标准输入的行,只把要保留的行原样写到标准输出(保持输入顺序)。保留的标准是按请求——设行中的 req= 值为 r,如果 int(hashlib.md5(r.encode()).hexdigest()[:8], 16) % N == 0,就保留该行。--rate 1 会全部保留。然后用 python3 sample.py --rate 10 < /opt/lab/logsample/app.log > /root/obs-log-sampling/sampled-10.log 生成结果文件。
因为判定是针对请求而不是针对行,所以一个请求的各行要么整体保留,要么整体消失。这就是这个过滤器的全部——从结果文件中随便挑一个 request_id 去 grep,行数与原文件相同。哈希方式必须原样使用任务中写明的那种。评分器会按同样的规则重新计算,并逐行比对。
以错误结束的请求不从采样中剔除
给 /root/obs-log-sampling/sample.py 增加 --keep-errors 选项。有这个选项时,只要有一行级别为 ERROR 的请求,无论采样率是多少,都保留它的所有行(保持输入顺序)。没有该选项时的行为必须与第 3 步相同。然后用 python3 sample.py --rate 10 --keep-errors < /opt/lab/logsample/app.log > /root/obs-log-sampling/sampled-10-err.log 生成结果。
哪个请求以错误结束,必须读完整个文件才知道,所以需要扫描两遍——先收集 ERROR 行的 request_id,再重新扫描各行并做判定。加入这条规则后,行数增加了多少,请与第 3 步的结果比较一下。增加得比想象的少。
把采样率与可调查性之间的权衡做成表
把采样率 N 依次改为 1、4、10、50,制作 /root/obs-log-sampling/tradeoff.tsv。没有表头,共四行,每行是以制表符分隔的五个字段 <N> <표본만 썼을 때 남은 줄 수> <그때 완전히 남은 오류 요청 수> <오류 보존까지 켰을 때 남은 줄 수> <그때 완전히 남은 오류 요청 수>(占位符依次为 N、仅用采样时剩余的行数、此时完整保留的错误请求数、同时启用错误保留时剩余的行数、此时完整保留的错误请求数)。“完整保留的错误请求”统计的是在以错误结束的请求中,结果文件里至少还剩一行的请求。
只需改变选项,运行 sample.py 八次。错误请求数可以用 grep ' ERROR ' <결과> | grep -o 'req=[0-9a-f]*' | sort -u | wc -l(占位符为结果文件)来统计。请看第三个字段在哪里变成 0,以及此时第四个字段比第二个字段增加了多少。
折叠重复并设置每秒上限
创建 /root/obs-log-sampling/squeeze.py。以 python3 squeeze.py [--max-debug-per-sec K] < 입력 > 출력(占位符依次为输入、输出;K 的默认值为 20)调用时,依次应用两条规则。① 如果与前一行的(级别、handler、msg)完全相同,就视为一组,只保留第一行,但如果该组的行数 k 大于等于 2,就在该行末尾附加 repeated=<k>。② 折叠之后,只对 DEBUG 行,在同一秒内(时间字符串的前 19 个字符)从前往后只保留 K 行,其余丢弃。然后生成 python3 squeeze.py < /opt/lab/logsample/app.log > /root/obs-log-sampling/squeezed.log,并在 /root/obs-log-sampling/squeeze.txt 中写四行 in_lines=、after_collapse=、after_cap=、bytes_saved_pct=<소수 두 자리>(占位符为保留两位小数的值)。
只有“连续”时才折叠——中间如果夹着其他请求的行,就是另一组。after_collapse 只要把上限设得非常大再运行一次来统计,就很容易得到。只对 DEBUG 设置上限,正是这一步的关键。如果不分级别地设置,在暴增的那一刻 ERROR 会被截掉,偏偏缺失的是最需要的时刻的日志。
应用 ① — 把两个过滤器串联起来,确认能否调查
把 sample.py --rate 10 --keep-errors 的输出直接交给 squeeze.py(默认上限),生成 /root/obs-log-sampling/final.log。然后在 /root/obs-log-sampling/final.txt 中写八行——in_lines=、out_lines=、in_bytes=、out_bytes=、reduction_pct=<바이트 기준, 소수 두 자리>(占位符为按字节计算、保留两位小数的值)、error_requests_kept=<final.log 에 줄이 남아 있는 오류 요청 수>(占位符为 final.log 中仍有行的错误请求数)、trace_req=<2단계에서 고른 그 요청 id>(占位符为第 2 步所选的那个请求的 ID)、trace_lines=<final.log 에 남은 그 요청의 줄 수>(占位符为 final.log 中剩余的该请求的行数)。
两个过滤器都使用标准输入输出,所以用管道连接即可。请把 trace_lines 与第 2 步的 req_lines_before 比较——与关掉 DEBUG 时有什么不同,就是本实验的结论。如果是重复被折叠的请求,行数也可能比原来更少。
应用 ② — 用策略文件固定级别、采样率、保留期限和成本
用 YAML 写 /root/obs-log-sampling/policy.yml。在 levels 之下,为 DEBUG、INFO、WARN、ERROR 四个级别各设置 retain_days(整数)和 sample_rate(整数)。ERROR 的 sample_rate 必须是 1,retain_days 必须大于 DEBUG。DEBUG 的 sample_rate 必须大于等于 2。在 rules 之下放 keep_errors_whole_request: true、collapse_repeats: true、max_debug_per_sec(第 6 步使用的默认值)。在 estimate 之下,把 raw_bytes、kept_bytes、reduction_pct 写成与第 7 步结果相同的值,最后用 note 以不少于 40 个字符的一句话写出这个策略的权衡。
请先用 python3 -c "import yaml,sys;yaml.safe_load(open('policy.yml'))" 确认语法。数字不要手工誊写,而是从 final.txt 中读取并填入,就不会出错。确定保留期限时,请问一问“几天之后还会有需要查找这个级别的时候吗”——季度复盘时查找的是 ERROR,而不是 DEBUG。