JianFeeeee
de6fa59cbb
## 起因
压测后重建网关，我发信做端到端验证，**pi 一直没回**。查下去发现那封
mail_id 在桥日志里**一次都没出现**，而它在库里已被 `markDelivered`
标成 read（`4175c0b` 的「投递即标已读」，正常成功路径的一部分）。
真正卡住排查的是：**池满时邮件进 `queue`，而排队路径一句日志都没有。**
于是「这封在排队」与「这封丢了」在日志上**完全同形** ——
当时能给出的结论只有「不知道」。
## 改法
入队/出队各一声，且都带可读数：
· 入队：key、第几位、前面还有几封、在跑 `activeCount/maxWorkers`、第几次尝试
· 出队：**等了多久**（秒）、剩几封在排
`attempt>1` 单独标出 —— 那是**重投**（上次没回报 done），与首次排队不是一回事，
混在一起会让人以为是同一种等待。
## ★ 两次错误归因（都记在 DEBTS 里，因为推理方式会复发）
**① 「是 read_inbox 连带标掉了在途邮件」** —— 错。
我看到 `status` 在 11ms 内变 read 就归因到 read_inbox。
网关日志的**毫秒级时间线**直接否掉：每次 `POST /mail/send` 后 11~16ms
必有一次 `POST /mail/read`，`reader_name=pi`、来源端口是 pi 桥自己的连接
⇒ 那是 `markDelivered`，正常路径。
**② 「是 opencode 的桥串用了 pi 的密钥」** —— 错。
我一度以为 `reader_name=pi` 与「连接来自 opencode 进程」矛盾。
实测两个 CONFIG_DIR 不同、各自的 key 在库里分别属于 pi / opencode。**没有串用。**
★ 共同点：**我先有了候选解释，再去找支持它的证据**。
正确顺序是「先取一条能一次说清的独立时间线，再解释」。
## 顺带纠正我自己上轮的一个测量假象
我曾说「实测同一时刻 4 个 worker 在跑，MAX_WORKERS=3 被绕过」——
**错的**。`pgrep -f` **把执行查询的那条命令自己算进去了**（它含同样的字符串）。
用 `ps -eo pid,args | grep -E "node .*/worker\.mjs$" | grep -v grep` 实测是 **3 个**，
与上限一致。探针把自己算进来 —— 与 `baseline-residue` / `python-probe-shadowing` 同族。
## 判据
新增 `test/queue-observability.test.mjs`（4 格，钉**形状**不钉读数 ——
读数要真把池压满才有）：
入队/出队各有一声、出队那声必须含等待时长、入队那声必须带占用比、
以及一条自检（删掉入队日志后源码里确实没有它 ⇒ 判据恒绿的话会先红）
变异验证：删掉入队日志 ⇒ **4 格全红**。
全套：pi 530 / opencode 351 / dsh 426，全绿；共用 lib 一致性 ✅。
52 lines
2.3 KiB
JavaScript
52 lines
2.3 KiB
JavaScript
/**
|
||
* ★ 排队路径必须出声（2026-09-28 加）
|
||
*
|
||
* 为什么有这条判据：池满时邮件进 `queue`，而**排队路径此前一句日志都没有**。
|
||
* 于是「这封在排队」与「这封丢了」在日志上**完全同形** ——
|
||
* 实测当天：发一封信，桥日志里那封 mail_id 一次都没出现，
|
||
* 而它在库里已被 `markDelivered` 标成 read。
|
||
* 当时能给出的结论只有「不知道」。
|
||
*
|
||
* 这条判据钉的是**形状**（源码里有入队/出队两声），不是读数 ——
|
||
* 读数要真的把池压满才有，而那要 3 个真 worker。
|
||
*/
|
||
import { test } from 'node:test';
|
||
import assert from 'node:assert/strict';
|
||
import { readFileSync } from 'node:fs';
|
||
import { fileURLToPath } from 'node:url';
|
||
import { dirname, join } from 'node:path';
|
||
|
||
const HERE = dirname(fileURLToPath(import.meta.url));
|
||
const src = readFileSync(join(HERE, '..', 'src', 'pool.mjs'), 'utf8');
|
||
|
||
test('入队与出队各有一声，且都带 key', () => {
|
||
const inQ = src.match(/log\(`排队 \$\{[^}]*\}/);
|
||
assert.ok(inQ, '入队必须打日志（否则「在排队」与「丢了」同形）');
|
||
|
||
const outQ = src.match(/log\(`出队 \$\{[^}]*\}/);
|
||
assert.ok(outQ, '出队必须打日志（否则不知道等了多久）');
|
||
});
|
||
|
||
test('★ 出队那一声要说出等了多久', () => {
|
||
// 只打「出队」不够：知道排过队，但不知道等了 2 秒还是 20 分钟。
|
||
// 这正是当天「不知道」的一部分 —— 读数里没有时间维度。
|
||
assert.match(src, /enqueuedAt/,
|
||
'入队时要记时间戳，否则算不出等待时长');
|
||
assert.match(src, /等了 \$\{waited/,
|
||
'出队那一声必须包含等待时长');
|
||
});
|
||
|
||
test('入队那一声要带当前占用，否则事后无法判断是不是池满导致', () => {
|
||
assert.match(src, /activeCount\(\)\}\/\$\{maxWorkers\}/,
|
||
'入队日志必须带 activeCount/maxWorkers —— 区分「池满」与「别的原因」');
|
||
});
|
||
|
||
test('判据有分辨力：去掉入队日志 ⇒ 本组必须变红', () => {
|
||
const stripped = src.replace(/log\(`排队 \$\{[\s\S]*?\}\);/, '');
|
||
assert.ok(
|
||
!/log\(`排队/.test(stripped),
|
||
'自检：删掉入队日志后源码里确实没有它 —— 否则这条判据恒绿'
|
||
);
|
||
assert.notEqual(stripped, src, '自检：变异确实改动了东西');
|
||
});
|