fix(pi桥): 排队路径补日志 —— 「在排队」与「丢了」此前在日志上同形

## 起因

压测后重建网关,我发信做端到端验证,**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 一致性 ✅。
This commit is contained in:
2026-09-28 10:40:01 +08:00
parent fffe6bf63a
commit de6fa59cbb
3 changed files with 77 additions and 7 deletions

View File

@ -132,7 +132,21 @@ export function createWorkerPool({
function submit(kind, data, attempt = 1) {
if (stopped) return;
queue.push({ kind, data, key: keyOf(data), attempt });
const before = queue.length;
queue.push({ kind, data, key: keyOf(data), attempt, enqueuedAt: Date.now() });
// ★ 入队/出队**必须出声**(2026-09-28 加)。
//
// 为什么:池满时邮件排队,而**排队路径此前一句日志都没有**。
// 于是「这封在排队」与「这封丢了」在日志上**完全同形** ——
// 实测 2026-09-28:发一封信,桥日志里那封 mail_id **一次都没出现**,
// 而它在库里已被 `markDelivered` 标成 read(见 docs/DEBTS.json 的
// `delivered-but-never-dispatched-silent`)。
// 当时能给出的结论只有「不知道」—— 判据与日志都不具备区分能力。
//
// 报「入队」而不是「在等」:`attempt>1` 说明是**重投**(上一次没回报 done),
// 那与首次排队是两回事,混在一起会让人以为是同一种等待。
log(`排队 ${queue[before].key}(第 ${before + 1} 位,前面还有 ${before} 封` +
`;在跑 ${activeCount()}/${maxWorkers}${attempt > 1 ? `,第 ${attempt} 次尝试` : ''})`);
pump();
}
@ -169,6 +183,11 @@ export function createWorkerPool({
if (activeCount() >= maxWorkers) return;
queue.splice(i, 1);
i--;
// ★ 与入队配对:让「等了多久」变成一个可读数。
// 没有它就只知道「排过队」,不知道是等了几秒还是根本没排上。
const waited = job.enqueuedAt ? Math.round((Date.now() - job.enqueuedAt) / 1000) : null;
log(`出队 ${job.key}(等了 ${waited === null ? '?' : waited + 's'};` +
`剩 ${queue.length} 封在排,在跑 ${activeCount()}/${maxWorkers})`);
spawn(job);
}
}

View File

@ -0,0 +1,51 @@
/**
* ★ 排队路径必须出声(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, '自检:变异确实改动了东西');
});