浏览 AI使用教程

偶发 Bug 怎样用日志、时间线和最小复现缩小范围

用一个 Node.js 缓存刷新竞态案例,把“每天偶尔 502”还原成请求时间线、成功/失败对照、最小复现代码和可重复回归测试。

故障现场

接口 99% 正常,缓存刚过期时两条并发请求偶尔一起失败

教学案例是一条 Node.js 商品接口:平时响应 200,运营每天第一次批量打开商品页时偶尔出现 502。最初日志只有“load failed”,没有请求 ID、节点、缓存状态或上游耗时,团队只能反复重启。

补齐日志后发现,失败只出现在 cache=expired 且同一节点 50 毫秒内收到多条请求时。两条请求同时刷新缓存,上游限并发后其中一条超时。这个结论来自失败与成功样本对照,不是看到‘缓存’两个字后的猜测。

  • 一条端到端故障时间线
  • 能稳定触发竞态的最小复现
  • 修复前后使用同一断言的回归结果
实际输入

先把四次请求排在同一时区,再找失败组独有条件

时间 UTC+8request_id节点缓存上游耗时结果
10:14:03.112req-81api-2hit0 ms200 / 42 ms
10:15:00.006req-82api-2expired1,980 ms200 / 2,014 ms
10:15:00.041req-83api-2expired5,000 ms502 / 5,018 ms
10:15:04.210req-84api-1hit0 ms200 / 39 ms

样本是为教学构造的最小数据。真实排查要保留原始日志、部署版本、时区和采集缺口。

代码现场

过期判断没有互斥,两条请求会同时进入刷新分支

问题代码

每个并发请求都会调用上游

let cache = { value: null, expiresAt: 0 };

export async function getCatalog() {
  if (Date.now() >= cache.expiresAt) {
    const value = await loadCatalogFromUpstream();
    cache = { value, expiresAt: Date.now() + 60_000 };
  }
  return cache.value;
}
最小复现

让 20 条请求在过期瞬间同时进入

cache.expiresAt = 0;
upstream.reset({ maxConcurrent: 1, delayMs: 80 });

const results = await Promise.allSettled(
  Array.from({ length: 20 }, () => getCatalog())
);

expect(upstream.calls).toBe(1);
expect(results.every(x => x.status === 'fulfilled')).toBe(true);

修复前第一条断言稳定失败,证明复现捕获的是并发刷新,而不是随机网络波动。

只改一个变量

用 single-flight 共享一次刷新,并保留失败后的重试能力

修复代码

同一进程只保留一个 refreshPromise

let cache = { value: null, expiresAt: 0 };
let refreshPromise = null;

export async function getCatalog() {
  if (Date.now() < cache.expiresAt) return cache.value;

  if (!refreshPromise) {
    refreshPromise = loadCatalogFromUpstream()
      .then(value => {
        cache = { value, expiresAt: Date.now() + 60_000 };
        return value;
      })
      .finally(() => { refreshPromise = null; });
  }

  return refreshPromise;
}

多实例部署仍可能同时刷新;若上游限制是全局的,还要评估分布式锁、抖动过期或允许陈旧值等方案。

中间结果与最终输出

同一组 20 并发请求,修复前后只比较三个指标

检查项修复前修复后通过标准
上游调用次数201同一进程一次过期窗口只刷新 1 次
fulfilled1-2 / 2020 / 2020 条全部返回有效目录
refreshPromise 失败后状态无此状态finally 后为 null下一次请求可以重新刷新
缓存命中路径约 40 ms约 40 ms正常路径无明显回归
常见失败

复现不稳定时,不要同时改超时、重试、缓存和日志

压力测试能失败,但与线上不是同一错误

原因
只追求出现 500,没有对齐状态码、调用链和失败位置。
怎么改
把线上 request_id 的时间线与复现逐字段对照;不一致就不是同一个 Bug。

加重试后看似恢复,调用量却暴涨

原因
重试掩盖了并发刷新,还把压力放大给上游。
怎么改
先验证根因;修复后再单独评估重试次数、退避和幂等。

本地 20 并发通过,线上仍偶发

原因
修复只在单进程内生效,线上有多个实例。
怎么改
把 node_id 加入日志,按实例与全局窗口重做对照。

只保留最终代码,没有故障证据

原因
无法证明修复针对原问题,也无法判断回归。
怎么改
保留原始样本、最小复现、diff、测试输出和观察窗口。
完整可运行小样

补齐上游桩与测试入口:三个用例无需外部服务

前面的片段解释竞态;以下是同一缓存机制的独立可执行练习。Node.js 20+,保存为 cache.test.mjs,运行 node --test cache.test.mjs。now由测试显式传入,不依赖真实等待。

cache.test.mjs

刷新合并、失败清理与过期回归

import test from 'node:test';
import assert from 'node:assert/strict';
function createCache(load, ttl = 100) {
 let value, expires = 0, inflight;
 return function getCatalog(now) {
  if (value !== undefined && now < expires) return Promise.resolve(value);
  if (inflight) return inflight;
  inflight = Promise.resolve().then(load).then(next => {
   value = next; expires = now + ttl; return next;
  }).finally(() => { inflight = undefined; });
  return inflight;
 };
}
test('同一实例并发只刷新一次', async () => {
 let calls = 0;
 const get = createCache(async () => { calls++; return ['book']; });
 assert.deepEqual(await Promise.all([get(0), get(0)]), [['book'], ['book']]);
 assert.equal(calls, 1);
});
test('刷新失败后下一次能重新尝试', async () => {
 let calls = 0;
 const get = createCache(async () => {
  calls++; if (calls === 1) throw new Error('upstream unavailable');
  return ['book'];
 });
 await assert.rejects(get(0), /upstream unavailable/);
 assert.deepEqual(await get(1), ['book']);
 assert.equal(calls, 2);
});
test('未过期命中,过期后刷新', async () => {
 let calls = 0;
 const get = createCache(async () => [++calls]);
 assert.deepEqual(await get(0), [1]);
 assert.deepEqual(await get(99), [1]);
 assert.deepEqual(await get(100), [2]);
 assert.equal(calls, 2);
});

预期3条通过;仅同一进程同一实例共享inflight,多实例仍需另行设计。失败分支finally必须释放inflight,否则后续可能一直复用失败Promise。不是生产上游调用记录。

验收方式

满足这些条件,才可以把“疑似竞态”写成已修复

核对入口

代码行为还要结合当前运行时与生产观测核验