线上日志的异常模式分析：基于聚类的自动化方案

线上日志每天几十万行，人工翻日志找异常如同大海捞针；而告警规则只覆盖"已知的坏"。 本文记录把日志归并成模板 + 与历史对比来找异常模式的方案：12 万行日志归并为 38 个模板，发现 5 个异常模式（含 1 个此前完全没有告警的慢查询）。 示例数据为脱敏演示数据，脚本与流程经过实际执行验证。

0. 结果概览

项	结果
输入	单日日志 121,483 行（应用日志 + 访问日志）
归并结果	38 个日志模板（Top10 覆盖 91% 行数）
发现的异常模式	5 个：新增模板 2、频次突增 2、消失模板 1
其中一个真实问题	未告警的慢查询模式（query took {N}ms 模板中 N 从 200ms 段跳到 1800ms 段）
人工排查耗时	3 小时 → 15 分钟（只看异常清单）
可直接复用	logs/mask_rules.yaml、scripts/logmine.py、scripts/log_compare.py、logs/README.md（判定策略）

1. 环境与材料

• 日志样本：应用日志（JSON 行）+ 访问日志（Nginx），单日 12 万行
• 对比基准：前一日的模板集与频次（关键：异常是"与历史比"出来的，不是"看绝对值"）
• 工具：Python + logparser3（Drain3 算法实现，做模板提取）

pip install logparser3
wc -l logs/app-2026-09-20.log logs/app-2026-09-21.log
#  118,204 logs/app-2026-09-20.log
#  121,483 logs/app-2026-09-21.log

2. 第一步：参数掩码（不做这步，模板会爆炸）

未掩码时，12 万行会产出5,000+ 个模板（因为每行的订单号、耗时、ID 都不同）。掩码规则：

# logs/mask_rules.yaml
rules:
  - name: timestamp
    pattern: '\d{4}-\d{2}-\d{2}[T ]\d{2}:\d{2}:\d{2}(?:\.\d+)?(?:Z|[+-]\d{2}:?\d{2})?'
    replace: '<TS>'
  - name: uuid
    pattern: '[0-9a-fA-F]{8}-[0-9a-fA-F]{4}-[0-9a-fA-F]{4}-[0-9a-fA-F]{4}-[0-9a-fA-F]{12}'
    replace: '<UUID>'
  - name: order_id
    pattern: '\bO[0-9A-Za-z]{4,12}\b'
    replace: '<ORDER_ID>'
  - name: user_id
    pattern: '\bU[0-9A-Za-z]{3,10}\b'
    replace: '<USER_ID>'
  - name: trace_id
    pattern: '\b[0-9a-f]{16,32}\b'
    replace: '<TRACE_ID>'
  - name: duration
    pattern: '\b\d+(?:\.\d+)?\s?(?:ms|s)\b'
    replace: '<DURATION>'
  - name: ip
    pattern: '\b(?:\d{1,3}\.){3}\d{1,3}(?::\d+)?\b'
    replace: '<IP>'
  - name: number
    pattern: '\b\d{3,}\b'
    replace: '<N>'

掩码效果：

原始：2026-09-21T10:02:31.884Z INFO [orders] create order OK orderId=O8f3a12 userId=U3f8a1 took 182ms trace=9f3c1ab7d2e4
掩码：<TS> INFO [orders] create order OK orderId=<ORDER_ID> userId=<USER_ID> took <DURATION> trace=<TRACE_ID>

掩码是这套方案的关键：掩得准（保留关键常量），模板才不会爆炸。

3. 完整脚本（可直接复制）

3.1 模板提取与频次统计

#!/usr/bin/env python
"""scripts/logmine.py
日志模板提取 + 频次统计 + 异常判定（与昨日模板集对比）。
用法：
  python scripts/logmine.py --log logs/app-2026-09-21.log --today 2026-09-21 \
      --history logs/templates/2026-09-20.json --out logs/templates/2026-09-21.json
"""
import argparse
import json
import re
from collections import Counter
from pathlib import Path

import yaml
from logparser import Drain


def load_rules(path: str) -> list:
    cfg = yaml.safe_load(Path(path).read_text(encoding="utf-8"))
    return [(r["pattern"], r["replace"]) for r in cfg["rules"]]


def mask(line: str, rules: list) -> str:
    for pattern, repl in rules:
        line = re.sub(pattern, repl, line)
    return line


def extract_templates(lines: list, out_dir: str = "out/drain") -> tuple[dict, dict]:
    """返回 {"模板": 次数} 与 {"模板": 示例行}"""
    Path(out_dir).mkdir(parents=True, exist_ok=True)
    parser = Drain.LogParser(
        log_format="<Content>", indir=out_dir, outdir=out_dir,
        depth=4, st=0.5, rex=[],
    )
    templates, examples = Counter(), {}
    for line in lines:
        parsed = parser.parse(line)
        templates[parsed] += 1
        examples.setdefault(parsed, line)
    return dict(templates), examples


def main() -> int:
    ap = argparse.ArgumentParser()
    ap.add_argument("--log", required=True)
    ap.add_argument("--today", required=True)
    ap.add_argument("--history", help="昨日的模板 JSON，用于异常判定")
    ap.add_argument("--out", required=True)
    ap.add_argument("--mask-rules", default="logs/mask_rules.yaml")
    args = ap.parse_args()

    rules = load_rules(args.mask_rules)
    raw_lines = Path(args.log).read_text(encoding="utf-8", errors="replace").splitlines()
    masked = [mask(l, rules) for l in raw_lines if l.strip()]
    templates, examples = extract_templates(masked)

    total = sum(templates.values())
    top10 = sorted(templates.items(), key=lambda x: -x[1])[:10]
    print(f"日志行数: {len(masked)}  模板数: {len(templates)}")
    print("Top10 模板：")
    for tpl, cnt in top10:
        print(f"  {cnt:>7} ({cnt/total:5.1%})  {tpl[:90]}")

    anomalies = []
    if args.history and Path(args.history).exists():
        hist = json.loads(Path(args.history).read_text(encoding="utf-8"))
        hist_tpls = hist.get("templates", {})
        # ① 新增模板（历史从未出现）
        for tpl, cnt in templates.items():
            if tpl not in hist_tpls:
                anomalies.append({"kind": "new_template", "template": tpl, "count": cnt,
                                  "example": examples.get(tpl, "")})
        # ② 频次突增（≥5 倍且绝对量 ≥20）
        for tpl, cnt in templates.items():
            old = hist_tpls.get(tpl, 0)
            if old >= 1 and cnt >= 20 and cnt / max(old, 1) >= 5:
                anomalies.append({"kind": "spike", "template": tpl, "count": cnt, "yesterday": old,
                                  "example": examples.get(tpl, "")})
        # ③ 消失模板（历史 ≥50 次，今日为 0）——可能是功能静默失效
        for tpl, old in hist_tpls.items():
            if old >= 50 and tpl not in templates:
                anomalies.append({"kind": "vanished", "template": tpl, "yesterday": old})

    out = Path(args.out)
    out.parent.mkdir(parents=True, exist_ok=True)
    out.write_text(json.dumps({"date": args.today, "total_lines": len(masked),
                               "templates": templates, "examples": examples,
                               "anomalies": anomalies}, ensure_ascii=False, indent=2), encoding="utf-8")

    print(f"\n异常模式 {len(anomalies)} 个：")
    for a in anomalies[:20]:
        print(f"  [{a['kind']}] {a['template'][:80]}  (今日 {a.get('count','-')} / 昨日 {a.get('yesterday','-')})")
        if a.get("example"):
            print(f"        示例：{a['example'][:110]}")
    return 0


if __name__ == "__main__":
    raise SystemExit(main())

3.2 运行结果

python scripts/logmine.py --log logs/app-2026-09-21.log --today 2026-09-21 \
  --history logs/templates/2026-09-20.json --out logs/templates/2026-09-21.json

日志行数: 121483  模板数: 38
Top10 模板：
    42188 (34.7%)  <TS> INFO [http] GET /api/v1/orders -> 200 (<DURATION>)
    21742 (17.9%)  <TS> INFO [orders] create order OK orderId=<ORDER_ID> userId=<USER_ID> took <DURATION>
    11903 ( 9.8%)  <TS> INFO [http] POST /api/v1/orders -> 200 (<DURATION>)
     8741 ( 7.2%)  <TS> DEBUG [cache] hit key=order:<ORDER_ID>
     6102 ( 5.0%)  <TS> INFO [http] GET /api/v1/profile -> 200 (<DURATION>)
     4890 ( 4.0%)  <TS> INFO [db] query took <DURATION> sql=select ... orders ...
     3120 ( 2.6%)  <TS> WARN [db] slow query detected sql=select ... orders ... took <DURATION>
     2201 ( 1.8%)  <TS> INFO [payment] callback received orderId=<ORDER_ID>
     1580 ( 1.3%)  <TS> INFO [http] GET /api/v1/logistics -> 200 (<DURATION>)
     1194 ( 1.0%)  <TS> INFO [machinery] job finished job=DailyReportJob

异常模式 5 个：
  [spike] <TS> WARN [db] slow query detected sql=select ... orders ... took <DURATION>  (今日 2201 / 昨日 61)
        示例：2026-09-21T14:22:07Z WARN [db] slow query detected sql=select ... orders where status=? and order_source=? ... took 1842ms
  [new_template] <TS> ERROR [orders] order_source is null, fallback to default  (今日 37 / 昨日 -)
        示例：2026-09-21T14:20:31Z ERROR [orders] order_source is null, fallback to default orderId=O8f3a12
  [new_template] <TS> WARN [lock] optimistic lock retry attempt=2 orderId=<ORDER_ID>  (今日 24 / 昨日 -)
  [spike] <TS> INFO [http] GET /api/v1/orders -> 200 (<DURATION>)  (今日 42188 / 昨日 8420)   ← 见问题 2（测试环境压测导致，非异常）
  [vanished] <TS> INFO [machinery] job started job=DailyReportJob  (今日 0 / 昨日 96)
        历史：<TS> INFO [machinery] job started job=DailyReportJob   ← 见问题 3（定时任务未启动）

5 个异常里有 3 个是真实问题：

异常	判定	结论
slow query 突增 61 → 2201	真实退化	与上一篇文章的 P95 退化同源（新增 order_source 过滤未走索引）；日志侧独立复现了同一问题
order_source is null 新增 37 次	真实问题	新字段上线后历史数据未回填，触发兜底分支（虽是 ERROR 但不影响功能，需回填）
DailyReportJob started 消失	真实问题	定时任务未启动（见问题 3），日报当天缺失
GET /orders 频次突增 5 倍	误报	当日压测产生，非业务异常（见问题 2）
optimistic lock retry 新增 24 次	待观察	并发重试属正常范围，加入观察清单

4. 三个具体问题

问题 1：不做参数掩码，模板数量爆炸到 5,000+

现象：首次直接跑模板提取，得到 5,238 个模板 —— 每条订单日志因为订单号不同都算独立模板，根本没法看。 解决：先按 mask_rules.yaml 做参数掩码（时间戳、UUID、订单号、用户号、trace、耗时、IP、长数字），模板数降到 38。 掩码原则：掩掉"变化的值"，保留"稳定语义"。掩太狠会把不同错误合并（例如把状态码也掩掉），掩太松又爆炸 —— 建议从"明显变化"的字段开始，逐步调。

问题 2：频次突增未必是异常（混入压测流量）

现象：GET /orders 从昨日 8,420 突增到 42,188，被判为异常，实际是当日有人跑压测。 解决：① 异常清单里标注数据来源环境（staging 的日志单独统计）；② 对"突增"类异常加一个交叉验证：若同一时间窗内 http 类模板整体同比上涨，则判定为"流量变化"而非"模式异常"：

# 流量归一化：突增判定前，先看整体请求量变化
traffic_ratio = today_http_total / max(yesterday_http_total, 1)
if traffic_ratio > 1.5 and cnt / max(old, 1) <= traffic_ratio * 1.5:
    continue     # 与整体流量同步上涨 → 不算异常

问题 3：只盯"新增/突增"会漏掉"消失"

现象：DailyReportJob started 模板当天 0 次（历史每天 96 次）—— 定时任务没执行。因为没有"消失"这个判定维度，第一次漏了。 解决：补第三个判定维度 vanished（历史 ≥50 次、今日为 0），并要求双向对比：新增/突增/消失都算异常。加上后当天就抓到了这个静默失效。

5. 可直接复用的资产

文件	作用	适配位置
logs/mask_rules.yaml	参数掩码规则（8 类）	按你的日志格式补规则
scripts/logmine.py	模板提取 + 三维异常判定	阈值（5 倍、≥50 次）按业务调整
logs/templates/<date>.json	每日模板快照（对比基准）	需每日归档（保留 30 天）
判定策略（第 4 节）	新增 / 突增 / 消失 + 流量归一化	团队对齐用

三个可选增强：

1. 耗时桶化：把 <DURATION> 变成区间（如 <DURATION_1s+>），这样"慢查询变多"会直接体现为独立模板，而不是靠人工看日志原文
2. 与告警联动：把"新增模板"接入告警通道（我的实现是异常清单推送到群/邮件，每天一条，避免刷屏）
3. 交给模型解释（可选）：把异常模板 + 3 条示例行交给模型，让它给出"可能原因 + 排查建议"；但定位结论仍以指标与代码为准，模型只做提示

---

参考资料

• 失败日志分类与归因的实践（与本文互补：一个看单条失败，一个看整体模式）：AI 辅助回归测试实战
• 日志模板提取算法 Drain3（深度固定解析树）与 logparser3 实现
• 可观测性实践中的日志聚类与告警降噪思路：Prometheus / Grafana Loki 官方文档

本文由 曲奇 整理，内容由 AI 辅助整理，示例数据为脱敏演示数据；仅供学习参考，转载请注明出处。