Skip to content

Commit 0414753

Browse files
committed
fix(service-messaging): SQL outbox 的 UPDATE 不再写 updated_at —— pnpm dev 控制台停止刷屏 (#4765)
空闲的 dev server 每秒稳定刷 48 行同一条 WARN,直到进程退出: WARN Field 'updated_at' is read-only — ignoring incoming change (#2948) `SqlNotificationOutbox.claim()` / `.claimDigest()` 和 `SqlHttpOutbox.claim()` 的第一步都是无条件的「reap stale in_flight」谓词 UPDATE —— visibility-timeout 回收,每个 dispatcher tick 都跑,不管有没有行真的过期 —— 而这些 payload 里都带了 `updated_at`。该列是 `readonly`,归 ObjectQL 内建的 `sys_stamp_audit_update` hook 所有,所以值先被 `stripReadonlyFields` 剥掉、再被平台盖回去:一次纯 no-op 的写,代价是一条 WARN。三条 claim 路径 × 8 个 partition × dispatcher 的 500ms tick = 48 行/秒,真正的 warn 和 error 全被冲走。 两个 outbox 的所有 UPDATE payload(`claim`、`claimDigest`、`ack`、`redeliver`) 现在都不再带 `updated_at`,交给平台 hook 盖 —— 存进去的行没有任何变化。INSERT 路径不动,照旧写两个审计列,且写成 `Date`:那里 `created_at` 是调用方拥有的,而 Postgres 的原生 `TIMESTAMP` 列会拒绝裸 epoch-ms 数字。 顺带清掉一个隐患:`enqueue()` 一直守着 `new Date()` 这条规矩,但 UPDATE 路径传的 是 epoch-ms 数字。之所以没炸,仅仅因为它在到达 driver 之前就被剥掉了 —— 一旦这些 写入哪天改走 system 上下文(system 上下文跳过剥离),这个数字就会直接落库。 回归测试断言两个 outbox 交给 engine 的 UPDATE payload 里不出现 `updated_at`, 其中包含「一行都不可 claim」的场景 —— 因为无条件 reap 正是刷屏的来源;同时锁住 INSERT 仍写 `Date`。已在真实 `pnpm dev`(showcase)上验证:120 秒 5469 行输出、 其中 5378 行是这条 WARN,修复后 90 秒 102 行,启动完成后不再有任何输出。 Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_018ipMgdweHC9LFSUdLByizr
1 parent 50185a8 commit 0414753

4 files changed

Lines changed: 260 additions & 10 deletions

File tree

Lines changed: 31 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,31 @@
1+
---
2+
'@objectstack/service-messaging': patch
3+
---
4+
5+
fix(service-messaging): stop the SQL outboxes from writing `updated_at` on UPDATE — `pnpm dev` no longer floods the console
6+
7+
An idle dev server printed the same warning 48 times a second, forever:
8+
9+
```
10+
WARN Field 'updated_at' is read-only — ignoring incoming change (#2948)
11+
```
12+
13+
`SqlNotificationOutbox.claim()` / `.claimDigest()` and `SqlHttpOutbox.claim()`
14+
open with an unconditional "reap stale in_flight" UPDATE — visibility-timeout
15+
recovery that runs on every dispatcher tick whether or not any row is actually
16+
stale — and every one of those payloads carried `updated_at`. That column is
17+
`readonly` and owned by ObjectQL's builtin `sys_stamp_audit_update` hook, so the
18+
value was stripped by `stripReadonlyFields` and re-stamped by the platform: a
19+
no-op write that cost one warning per call. Three claim paths × 8 partitions ×
20+
the dispatcher's 500 ms tick = 48 identical lines a second, which buried every
21+
real warning and error in the dev log.
22+
23+
`updated_at` is now gone from every UPDATE payload in both outboxes (`claim`,
24+
`claimDigest`, `ack`, `redeliver`); the platform hook keeps stamping it, so
25+
stored rows are unchanged. INSERT still writes both audit columns, as `Date`s —
26+
`created_at` is caller-owned there, and a native `TIMESTAMP` column rejects a
27+
bare epoch-ms number on Postgres.
28+
29+
That last point was also a latent bug this removes: `enqueue()` correctly used
30+
`new Date()`, but the UPDATE paths passed epoch-ms numbers. Nothing broke only
31+
because the strip discarded them before they reached the driver.

packages/services/service-messaging/src/sql-http-outbox.ts

Lines changed: 9 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -63,6 +63,13 @@ interface DeliveryRow {
6363
* `UPDATE WHERE status='pending'` for the exactly-once claim; precomputed
6464
* `partition_key`; SELECT-then-INSERT dedup converging on the unique index).
6565
* Dedup uniqueness is `(source, dedup_key)`; partition affinity is on `ref_id`.
66+
*
67+
* **No UPDATE here writes `updated_at`** (#4765) — same rule, same reason as
68+
* {@link SqlNotificationOutbox}: the platform's `sys_stamp_audit_update` hook
69+
* owns that column, a caller-supplied value is stripped as `readonly` (#2948)
70+
* with a WARN per call, and `claim()`'s unconditional reap UPDATE runs on every
71+
* dispatcher tick — so writing it turned an idle dev server into a console
72+
* firehose while changing nothing about the stored row.
6673
*/
6774
export class SqlHttpOutbox implements IHttpOutbox {
6875
private readonly objectName: string;
@@ -127,7 +134,7 @@ export class SqlHttpOutbox implements IHttpOutbox {
127134
// 1. Reap stale in_flight rows — visibility-timeout recovery.
128135
await this.engine.update(
129136
this.objectName,
130-
{ status: 'pending', claimed_by: null, claimed_at: null, updated_at: now },
137+
{ status: 'pending', claimed_by: null, claimed_at: null },
131138
{
132139
where: {
133140
status: 'in_flight',
@@ -155,7 +162,7 @@ export class SqlHttpOutbox implements IHttpOutbox {
155162
// 3. Atomic claim. WHERE status='pending' rejects rows another worker took.
156163
await this.engine.update(
157164
this.objectName,
158-
{ status: 'in_flight', claimed_by: opts.nodeId, claimed_at: now, updated_at: now },
165+
{ status: 'in_flight', claimed_by: opts.nodeId, claimed_at: now },
159166
{ where: { id: { $in: ids }, status: 'pending' }, multi: true },
160167
);
161168

@@ -205,7 +212,6 @@ export class SqlHttpOutbox implements IHttpOutbox {
205212
response_body: result.responseBody ?? null,
206213
next_retry_at: nextRetryAt,
207214
error,
208-
updated_at: now,
209215
},
210216
{ where: { id }, multi: false },
211217
);
@@ -230,7 +236,6 @@ export class SqlHttpOutbox implements IHttpOutbox {
230236
'DELIVERY_NOT_ELIGIBLE',
231237
);
232238
}
233-
const now = Date.now();
234239
await this.engine.update(
235240
this.objectName,
236241
{
@@ -243,7 +248,6 @@ export class SqlHttpOutbox implements IHttpOutbox {
243248
response_code: null,
244249
response_body: null,
245250
error: null,
246-
updated_at: now,
247251
},
248252
{ where: { id, status: { $in: ['success', 'failed', 'dead'] } }, multi: false },
249253
);
Lines changed: 204 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,204 @@
1+
// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license.
2+
3+
/**
4+
* #4765 — the SQL outboxes must never put `updated_at` in an UPDATE payload.
5+
*
6+
* ObjectQL's builtin `sys_stamp_audit_update` hook owns that column on every
7+
* update, and the column is `readonly`, so a caller-supplied value is stripped
8+
* by `stripReadonlyFields` (#2948) — which WARNs once per call. `claim()` and
9+
* `claimDigest()` open with an unconditional "reap stale in_flight" UPDATE that
10+
* runs on every dispatcher tick whether or not a row is stale, so the write was
11+
* both a no-op (stripped, then re-stamped) and, at 3 claim paths × 8 partitions
12+
* × a 500 ms tick, 48 identical warnings a second on an idle `pnpm dev`.
13+
*
14+
* INSERT is a different path (no strip, and `created_at` IS caller-owned): it
15+
* keeps writing both audit columns, as `Date`s — a native TIMESTAMP column
16+
* rejects a bare epoch-ms number on Postgres (see `audit-timestamp.ts`).
17+
*/
18+
19+
import { describe, it, expect } from 'vitest';
20+
import type { IDataEngine } from '@objectstack/spec/contracts';
21+
import { SqlNotificationOutbox } from './sql-outbox.js';
22+
import { SqlHttpOutbox } from './sql-http-outbox.js';
23+
24+
interface RecordedUpdate {
25+
object: string;
26+
data: Record<string, unknown>;
27+
}
28+
29+
/**
30+
* Minimal recording `IDataEngine`. `find` replays a scripted queue of result
31+
* sets so a claim can be driven all the way through candidate-select →
32+
* atomic-claim → read-back; everything else is inert.
33+
*/
34+
function makeEngine(findResults: Array<Array<Record<string, unknown>>> = []) {
35+
const updates: RecordedUpdate[] = [];
36+
const inserts: Array<{ object: string; data: Record<string, unknown> }> = [];
37+
let findCall = 0;
38+
39+
const engine = {
40+
async insert(object: string, data: Record<string, unknown>) {
41+
inserts.push({ object, data });
42+
return data;
43+
},
44+
async update(object: string, data: Record<string, unknown>) {
45+
updates.push({ object, data });
46+
return { matched: 0, modified: 0 };
47+
},
48+
async find(_object: string) {
49+
return findResults[findCall++] ?? [];
50+
},
51+
async findOne(_object: string, opts?: { fields?: string[] }) {
52+
// `ack()` reads the current attempt count; `enqueue()` probes for a
53+
// dedup winner and must miss so the insert path runs.
54+
if (opts?.fields?.includes('attempts')) return { attempts: 2 };
55+
return null;
56+
},
57+
async delete() { return { matched: 0, modified: 0 }; },
58+
} as unknown as IDataEngine;
59+
60+
return { engine, updates, inserts };
61+
}
62+
63+
/** Every audit column an UPDATE payload must leave to the platform. */
64+
const PLATFORM_OWNED_ON_UPDATE = ['updated_at'];
65+
66+
function expectNoPlatformAuditColumns(updates: RecordedUpdate[]) {
67+
expect(updates.length).toBeGreaterThan(0);
68+
for (const u of updates) {
69+
for (const column of PLATFORM_OWNED_ON_UPDATE) {
70+
expect(
71+
Object.prototype.hasOwnProperty.call(u.data, column),
72+
`UPDATE on ${u.object} must not write '${column}' — keys: ${Object.keys(u.data).join(', ')}`,
73+
).toBe(false);
74+
}
75+
}
76+
}
77+
78+
describe('SqlNotificationOutbox — audit columns on UPDATE (#4765)', () => {
79+
it('claim() writes no updated_at (reap + atomic claim)', async () => {
80+
// find #1 → candidate ids; find #2 → read-back of the rows we own.
81+
const { engine, updates } = makeEngine([[{ id: 'd1' }], []]);
82+
const outbox = new SqlNotificationOutbox(engine, { partitionCount: 8 });
83+
84+
await outbox.claim({ nodeId: 'n1', limit: 10, claimTtlMs: 1000 });
85+
86+
// Both the unconditional reap and the atomic claim ran.
87+
expect(updates).toHaveLength(2);
88+
expectNoPlatformAuditColumns(updates);
89+
// The claim still stamps its OWN columns — this is not a blanket strip.
90+
expect(updates[1].data).toMatchObject({ status: 'in_flight', claimed_by: 'n1' });
91+
expect(updates[1].data.claimed_at).toEqual(expect.any(Number));
92+
});
93+
94+
it('claim() writes no updated_at even when nothing is claimable', async () => {
95+
// The reap UPDATE fires on every tick regardless — that is the firehose.
96+
const { engine, updates } = makeEngine([[]]);
97+
const outbox = new SqlNotificationOutbox(engine, { partitionCount: 8 });
98+
99+
await outbox.claim({ nodeId: 'n1', limit: 10, claimTtlMs: 1000 });
100+
101+
expect(updates).toHaveLength(1);
102+
expectNoPlatformAuditColumns(updates);
103+
});
104+
105+
it('claimDigest() writes no updated_at', async () => {
106+
const { engine, updates } = makeEngine([[{ id: 'd1' }], []]);
107+
const outbox = new SqlNotificationOutbox(engine, { partitionCount: 8 });
108+
109+
await outbox.claimDigest({ nodeId: 'n1', limit: 10, claimTtlMs: 1000 });
110+
111+
expect(updates).toHaveLength(2);
112+
expectNoPlatformAuditColumns(updates);
113+
});
114+
115+
it('ack() writes no updated_at but still bumps its own columns', async () => {
116+
const { engine, updates } = makeEngine();
117+
const outbox = new SqlNotificationOutbox(engine, { partitionCount: 8 });
118+
119+
await outbox.ack('d1', { success: false, error: 'boom', nextAttemptAt: 123 });
120+
121+
expectNoPlatformAuditColumns(updates);
122+
expect(updates[0].data).toMatchObject({
123+
status: 'pending',
124+
attempts: 3, // 2 (read back) + 1
125+
error: 'boom',
126+
next_attempt_at: 123,
127+
});
128+
});
129+
130+
it('enqueue() still writes both audit columns as Dates on INSERT', async () => {
131+
const { engine, inserts } = makeEngine();
132+
const outbox = new SqlNotificationOutbox(engine, { partitionCount: 8 });
133+
134+
await outbox.enqueue({ notificationId: 'n1', recipientId: 'u1', channel: 'email', payload: {} });
135+
136+
expect(inserts).toHaveLength(1);
137+
expect(inserts[0].data.created_at).toBeInstanceOf(Date);
138+
expect(inserts[0].data.updated_at).toBeInstanceOf(Date);
139+
});
140+
});
141+
142+
describe('SqlHttpOutbox — audit columns on UPDATE (#4765)', () => {
143+
const enqueueInput = {
144+
source: 'flow',
145+
refId: 'r1',
146+
dedupKey: 'd1',
147+
url: 'https://example.test/hook',
148+
payload: { hello: 'world' },
149+
};
150+
151+
it('claim() writes no updated_at (reap + atomic claim)', async () => {
152+
const { engine, updates } = makeEngine([[{ id: 'h1' }], []]);
153+
const outbox = new SqlHttpOutbox(engine, { partitionCount: 8 });
154+
155+
await outbox.claim({ nodeId: 'n1', limit: 10, claimTtlMs: 1000 });
156+
157+
expect(updates).toHaveLength(2);
158+
expectNoPlatformAuditColumns(updates);
159+
expect(updates[1].data).toMatchObject({ status: 'in_flight', claimed_by: 'n1' });
160+
});
161+
162+
it('claim() writes no updated_at even when nothing is claimable', async () => {
163+
const { engine, updates } = makeEngine([[]]);
164+
const outbox = new SqlHttpOutbox(engine, { partitionCount: 8 });
165+
166+
await outbox.claim({ nodeId: 'n1', limit: 10, claimTtlMs: 1000 });
167+
168+
expect(updates).toHaveLength(1);
169+
expectNoPlatformAuditColumns(updates);
170+
});
171+
172+
it('ack() writes no updated_at but still bumps its own columns', async () => {
173+
const { engine, updates } = makeEngine();
174+
const outbox = new SqlHttpOutbox(engine, { partitionCount: 8 });
175+
176+
await outbox.ack('h1', {
177+
success: false,
178+
error: 'boom',
179+
httpStatus: 503,
180+
nextRetryAt: 456,
181+
durationMs: 12,
182+
});
183+
184+
expectNoPlatformAuditColumns(updates);
185+
expect(updates[0].data).toMatchObject({
186+
status: 'pending',
187+
attempts: 3,
188+
error: 'boom',
189+
response_code: 503,
190+
next_retry_at: 456,
191+
});
192+
});
193+
194+
it('enqueue() still writes both audit columns as Dates on INSERT', async () => {
195+
const { engine, inserts } = makeEngine();
196+
const outbox = new SqlHttpOutbox(engine, { partitionCount: 8 });
197+
198+
await outbox.enqueue(enqueueInput);
199+
200+
expect(inserts).toHaveLength(1);
201+
expect(inserts[0].data.created_at).toBeInstanceOf(Date);
202+
expect(inserts[0].data.updated_at).toBeInstanceOf(Date);
203+
});
204+
});

packages/services/service-messaging/src/sql-outbox.ts

Lines changed: 16 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -53,6 +53,18 @@ interface DeliveryRow {
5353
* `UPDATE … WHERE status='pending'` claim. `partition_key` is precomputed on
5454
* enqueue (ObjectQL has no portable `hash()` in WHERE). Mirrors
5555
* `SqlWebhookOutbox`.
56+
*
57+
* **No UPDATE here writes `updated_at`** (#4765). ObjectQL's builtin
58+
* `sys_stamp_audit_update` hook stamps it on every update unconditionally, and
59+
* `updated_at` is `readonly`, so a caller-supplied value is stripped by
60+
* `stripReadonlyFields` (#2948) before it reaches the driver — with a WARN per
61+
* call. `claim()` / `claimDigest()` start with an unconditional reap UPDATE that
62+
* runs whether or not a row is stale, so on an idle dev server the three claim
63+
* paths × 8 partitions × a 500 ms dispatcher tick spammed 48 identical warnings
64+
* a second and drowned the console. Writing the column was already a no-op
65+
* (stripped, then re-stamped); passing it as epoch-ms would also have been the
66+
* wrong shape for a native TIMESTAMP column (see `toEpochMs`) had it ever
67+
* survived the strip. Leave it to the platform.
5668
*/
5769
export class SqlNotificationOutbox implements INotificationOutbox {
5870
private readonly objectName: string;
@@ -114,7 +126,7 @@ export class SqlNotificationOutbox implements INotificationOutbox {
114126
// 1. Reap stale in_flight rows (visibility-timeout recovery).
115127
await this.engine.update(
116128
this.objectName,
117-
{ status: 'pending', claimed_by: null, claimed_at: null, updated_at: now },
129+
{ status: 'pending', claimed_by: null, claimed_at: null },
118130
{ where: { status: 'in_flight', claimed_at: { $lt: now - opts.claimTtlMs } }, multi: true } as any,
119131
);
120132

@@ -137,7 +149,7 @@ export class SqlNotificationOutbox implements INotificationOutbox {
137149
// 3. Atomic claim — WHERE status='pending' rejects rows another worker took.
138150
await this.engine.update(
139151
this.objectName,
140-
{ status: 'in_flight', claimed_by: opts.nodeId, claimed_at: now, updated_at: now },
152+
{ status: 'in_flight', claimed_by: opts.nodeId, claimed_at: now },
141153
{ where: { id: { $in: ids }, status: 'pending' }, multi: true } as any,
142154
);
143155

@@ -154,7 +166,7 @@ export class SqlNotificationOutbox implements INotificationOutbox {
154166
// 1. Reap stale in_flight (same as claim).
155167
await this.engine.update(
156168
this.objectName,
157-
{ status: 'pending', claimed_by: null, claimed_at: null, updated_at: now },
169+
{ status: 'pending', claimed_by: null, claimed_at: null },
158170
{ where: { status: 'in_flight', claimed_at: { $lt: now - opts.claimTtlMs } }, multi: true } as any,
159171
);
160172

@@ -177,7 +189,7 @@ export class SqlNotificationOutbox implements INotificationOutbox {
177189
// 3. Atomic claim.
178190
await this.engine.update(
179191
this.objectName,
180-
{ status: 'in_flight', claimed_by: opts.nodeId, claimed_at: now, updated_at: now },
192+
{ status: 'in_flight', claimed_by: opts.nodeId, claimed_at: now },
181193
{ where: { id: { $in: ids }, status: 'pending' }, multi: true } as any,
182194
);
183195

@@ -224,7 +236,6 @@ export class SqlNotificationOutbox implements INotificationOutbox {
224236
claimed_at: null,
225237
next_attempt_at: nextAttemptAt,
226238
error,
227-
updated_at: now,
228239
},
229240
{ where: { id }, multi: false } as any,
230241
);

0 commit comments

Comments
 (0)