Skip to content

Commit 03f1fa0

Browse files
committed
fix(webapp): honest watch check data semantics (review F8-F10)
- a stale queuedAt is never labeled as queue latency — resumed/retrying runs report time from creation - a stale zero depth bucket can't declare a drain: satisfied requires a live counter or a provably fresh bucket, else unavailable - error recurrence uses errors_v1 last_seen (ms precision), includes the creation minute, and marks approximate counts instead of overclaiming
1 parent f63c955 commit 03f1fa0

3 files changed

Lines changed: 332 additions & 45 deletions

File tree

apps/webapp/app/services/dashboardAgentWatchChecks.server.ts

Lines changed: 120 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -10,7 +10,8 @@
1010
* same seam the queue pages and the waiting-run module use — with the
1111
* ClickHouse depth series as fallback.
1212
* - queue existence: ONE Postgres `TaskQueue` point-read.
13-
* - error recurrence: ClickHouse `error_occurrences_v1` only.
13+
* - error recurrence: ClickHouse `errors_v1` for WHETHER it recurred (millisecond
14+
* `last_seen`), plus the per-minute `error_occurrences_v1` rollup for the count.
1415
* - health: the existing health report (loader + interpreter), unchanged.
1516
*
1617
* Readers THROW on failure rather than swallowing it, because `checkWatch` turns a
@@ -69,16 +70,32 @@ export async function watchQueueExists(environmentId: string, queueName: string)
6970
/** How far back the ClickHouse depth fallback looks when the live counter is down. */
7071
const DEPTH_FALLBACK_MINUTES = 10;
7172
const DEPTH_FALLBACK_BUCKET_SECONDS = 60;
73+
/**
74+
* How far behind `now` the newest analytics bucket may END and still be read as
75+
* "the queue right now". One bucket of slack: anything older leaves a gap the
76+
* rollup hasn't covered, and runs queued in that gap would be invisible.
77+
*/
78+
const DEPTH_FRESH_TOLERANCE_MS = DEPTH_FALLBACK_BUCKET_SECONDS * 1000;
7279

7380
function formatClickhouseDateTime(date: Date): string {
7481
return date.toISOString().slice(0, 19).replace("T", " ");
7582
}
7683

84+
/** ClickHouse renders DateTime without a zone; the column is UTC. */
85+
function parseClickhouseDateTime(value: string): Date {
86+
return new Date(`${value.replace(" ", "T")}Z`);
87+
}
88+
7789
/**
7890
* Current pending count for one queue. The live run-queue counter is the truth
7991
* ("is it drained RIGHT NOW"); ClickHouse is the fallback and reports the most
80-
* recent bucket's PEAK depth, which can only over-report — so a fallback zero
81-
* still means "nothing was queued in that bucket", never a false drain.
92+
* recent bucket's PEAK depth, which can only over-report within that bucket.
93+
*
94+
* The fallback carries `current`, and it is false unless the newest bucket
95+
* actually reaches the present: a rollup that's minutes behind may hold an empty
96+
* bucket while runs piled up after it, and reading that as "drained" is the one
97+
* mistake this watch must never make. `checkBacklogDrain` turns a stale zero into
98+
* `unavailable`.
8299
*/
83100
export async function readWatchQueueDepth(
84101
environment: AuthenticatedEnvironment,
@@ -87,7 +104,7 @@ export async function readWatchQueueDepth(
87104
): Promise<WatchQueueDepth | null> {
88105
const live = await engine.lengthOfQueue(environment, queueName).catch(() => null);
89106
if (typeof live === "number" && Number.isFinite(live)) {
90-
return { depth: live, source: "live_queue" };
107+
return { depth: live, source: "live_queue", current: true, asOf: now };
91108
}
92109

93110
const clickhouse = await clickhouseFactory.getClickhouseForOrganization(
@@ -114,18 +131,66 @@ export async function readWatchQueueDepth(
114131

115132
// Newest bucket wins — the closest thing the rollup has to "now".
116133
const newest = rows.reduce((best, row) => (row.bucket > best.bucket ? row : best), rows[0]!);
117-
return { depth: newest.depth, source: "queue_metrics" };
134+
const bucketEnd = new Date(parseClickhouseDateTime(newest.bucket).getTime() + bucketMs);
135+
const current = bucketEnd.getTime() >= now.getTime() - DEPTH_FRESH_TOLERANCE_MS;
136+
137+
return { depth: newest.depth, source: "queue_metrics", current, asOf: bucketEnd };
138+
}
139+
140+
const MINUTE_MS = 60_000;
141+
142+
type OrganizationClickhouse = Awaited<
143+
ReturnType<typeof clickhouseFactory.getClickhouseForOrganization>
144+
>;
145+
146+
/**
147+
* The fingerprint's most recent occurrence, at MILLISECOND precision, from the
148+
* `errors_v1` aggregate (`max(last_seen)` over every task that produced it).
149+
*
150+
* This is what makes "has it come back?" answerable exactly. The per-minute
151+
* `error_occurrences_v1` rollup can only place an error in a minute, and the
152+
* minute a watch is created in holds BOTH the error that prompted the watch and
153+
* any recurrence seconds later — so the rollup alone can neither confirm nor deny
154+
* a recurrence in that first minute.
155+
*/
156+
async function readErrorLastSeen(
157+
clickhouse: OrganizationClickhouse,
158+
environment: AuthenticatedEnvironment,
159+
fingerprint: string
160+
): Promise<Date | null> {
161+
const builder = clickhouse.errors.activeErrorsSinceQueryBuilder();
162+
builder.where("organization_id = {organizationId: String}", {
163+
organizationId: environment.organizationId,
164+
});
165+
builder.where("project_id = {projectId: String}", { projectId: environment.projectId });
166+
builder.where("environment_id = {environmentId: String}", { environmentId: environment.id });
167+
builder.where("error_fingerprint = {fingerprint: String}", { fingerprint });
168+
builder.groupBy("environment_id, task_identifier, error_fingerprint");
169+
170+
const [error, rows] = await builder.execute();
171+
if (error) throw error;
172+
if (!rows || rows.length === 0) return null;
173+
174+
let lastSeenMs = 0;
175+
for (const row of rows) {
176+
const ms = Number(row.last_seen);
177+
if (Number.isFinite(ms) && ms > lastSeenMs) lastSeenMs = ms;
178+
}
179+
180+
return lastSeenMs > 0 ? new Date(lastSeenMs) : null;
118181
}
119182

120183
/**
121-
* The first occurrence of an error fingerprint after `since`, from the per-minute
122-
* `error_occurrences_v1` rollup.
184+
* What we know about an error fingerprint relative to `since`, from two reads that
185+
* each answer what only they can:
123186
*
124-
* Buckets are filtered with `minute > since`, i.e. STRICTLY after, so an
125-
* occurrence in the same minute the watch was created can't be read as a
126-
* recurrence. That under-counts by at most the creation minute — the conservative
127-
* direction, since a watch must never fire on the error that prompted it.
128-
* `occurredAt` is therefore minute-granular by construction.
187+
* - `errors_v1` decides WHETHER it recurred, to the millisecond. An occurrence
188+
* 40 seconds after the watch was created is a recurrence, and rounding the
189+
* window up to the next minute used to lose it entirely.
190+
* - `error_occurrences_v1` supplies HOW MANY and, for minutes after the creation
191+
* minute, when. Its creation-minute bucket can't be split between the original
192+
* error and a recurrence, so those occurrences only make `countSince` a lower
193+
* bound (`countApproximate`) — never a claim.
129194
*/
130195
export async function readWatchErrorRecurrence(
131196
environment: AuthenticatedEnvironment,
@@ -137,31 +202,66 @@ export async function readWatchErrorRecurrence(
137202
"logs"
138203
);
139204

205+
const lastSeenAt = await readErrorLastSeen(clickhouse, environment, fingerprint);
206+
// Never seen in this environment at all.
207+
if (!lastSeenAt) return null;
208+
209+
const notRecurred: WatchErrorRecurrence = {
210+
occurredAt: null,
211+
occurredAtPrecision: null,
212+
countSince: 0,
213+
countApproximate: false,
214+
lastSeenAt,
215+
};
216+
if (lastSeenAt.getTime() <= since.getTime()) return notRecurred;
217+
218+
// Something landed after `since`. The rollup fills in the count and the minute.
219+
const sinceMinuteMs = Math.floor(since.getTime() / MINUTE_MS) * MINUTE_MS;
140220
const queryBuilder = clickhouse.errors.createOccurrencesQueryBuilder("INTERVAL 1 MINUTE");
141221
queryBuilder.where("organization_id = {organizationId: String}", {
142222
organizationId: environment.organizationId,
143223
});
144224
queryBuilder.where("project_id = {projectId: String}", { projectId: environment.projectId });
145225
queryBuilder.where("environment_id = {environmentId: String}", { environmentId: environment.id });
146226
queryBuilder.where("error_fingerprint = {fingerprint: String}", { fingerprint });
147-
queryBuilder.where("minute > toStartOfMinute(fromUnixTimestamp64Milli({sinceMs: Int64}))", {
227+
// The creation minute is INCLUDED — its occurrences are what the old
228+
// `minute > since` filter dropped.
229+
queryBuilder.where("minute >= toStartOfMinute(fromUnixTimestamp64Milli({sinceMs: Int64}))", {
148230
sinceMs: since.getTime(),
149231
});
150232
queryBuilder.groupBy("error_fingerprint, bucket_epoch");
151233
queryBuilder.orderBy("bucket_epoch ASC");
152234

153235
const [error, rows] = await queryBuilder.execute();
154236
if (error) throw error;
155-
if (!rows || rows.length === 0) return null;
156237

157-
let earliest = rows[0]!.bucket_epoch;
158-
let countSince = 0;
159-
for (const row of rows) {
160-
if (row.bucket_epoch < earliest) earliest = row.bucket_epoch;
161-
countSince += row.count;
238+
let earliestAfterMs: number | null = null;
239+
let countAfter = 0;
240+
let creationMinuteCount = 0;
241+
242+
for (const row of rows ?? []) {
243+
const bucketMs = row.bucket_epoch * 1000;
244+
if (bucketMs <= sinceMinuteMs) {
245+
creationMinuteCount += row.count;
246+
continue;
247+
}
248+
countAfter += row.count;
249+
if (earliestAfterMs === null || bucketMs < earliestAfterMs) earliestAfterMs = bucketMs;
162250
}
163251

164-
return { occurredAt: new Date(earliest * 1000), countSince };
252+
// The earliest time we can PROVE an occurrence at: a bucket that starts after
253+
// the creation minute, or — when the only evidence is in that minute, or the
254+
// rollup hasn't caught up — the exact `last_seen`.
255+
const useBucket = earliestAfterMs !== null && earliestAfterMs < lastSeenAt.getTime();
256+
257+
return {
258+
occurredAt: useBucket ? new Date(earliestAfterMs!) : lastSeenAt,
259+
occurredAtPrecision: useBucket ? "minute" : "exact",
260+
// At least the one `errors_v1` proved, even if the rollup lags behind it.
261+
countSince: Math.max(1, countAfter),
262+
countApproximate: creationMinuteCount > 0,
263+
lastSeenAt,
264+
};
165265
}
166266

167267
const HEALTH_SEVERITIES = new Set<string>(["ok", "warn", "crit"]);

apps/webapp/app/services/dashboardAgentWatchChecks.ts

Lines changed: 80 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -41,16 +41,38 @@ export type WatchRunRow = {
4141
};
4242

4343
export type WatchQueueDepth = {
44-
/** Current pending count for the queue. */
44+
/** Pending count for the queue, as of `asOf`. */
4545
depth: number;
4646
source: "live_queue" | "queue_metrics";
47+
/**
48+
* Whether the reading describes the queue RIGHT NOW. A live counter always
49+
* does; an analytics bucket only does while it's fresh enough to cover the
50+
* present. A stale reading can never answer "drained" — see
51+
* `checkBacklogDrain`.
52+
*/
53+
current: boolean;
54+
/** What instant the reading describes, when it isn't the live counter. */
55+
asOf?: Date;
4756
};
4857

49-
/** The first occurrence of the watched error after the watch's `since`, if any. */
58+
/** What we know about the watched error's occurrences relative to `since`. */
5059
export type WatchErrorRecurrence = {
51-
occurredAt: Date;
52-
/** Occurrences counted in the same window. */
60+
/**
61+
* The earliest occurrence PROVEN to be after `since`, or null when nothing has
62+
* recurred. Null with a `lastSeenAt` means "seen before, not since".
63+
*/
64+
occurredAt: Date | null;
65+
/** How precisely `occurredAt` is known: to the millisecond, or to its minute. */
66+
occurredAtPrecision: "exact" | "minute" | null;
67+
/** Occurrences after `since`. A LOWER BOUND when `countApproximate`. */
5368
countSince: number;
69+
/**
70+
* True when `countSince` can't be split exactly — occurrences in the minute
71+
* the watch was created can't be told apart from the error that prompted it.
72+
*/
73+
countApproximate: boolean;
74+
/** The fingerprint's most recent occurrence, whenever it was. */
75+
lastSeenAt: Date | null;
5476
};
5577

5678
export type WatchHealthSeverity = "ok" | "warn" | "crit";
@@ -73,7 +95,10 @@ export type WatchCheckDeps = {
7395
queueExists: (queue: string) => Promise<boolean>;
7496
/** Current pending count, live run-queue first with a ClickHouse fallback. */
7597
readQueueDepth: (queue: string) => Promise<WatchQueueDepth | null>;
76-
/** First occurrence of `fingerprint` strictly after `since`, plus the count. */
98+
/**
99+
* What's known about `fingerprint` relative to `since`. `null` means the
100+
* fingerprint has no occurrences at all in this environment.
101+
*/
77102
readErrorRecurrence: (fingerprint: string, since: Date) => Promise<WatchErrorRecurrence | null>;
78103
/** The health report's current verdict for the watch's environment. */
79104
readHealth: () => Promise<WatchHealthSnapshot | null>;
@@ -129,9 +154,14 @@ function formatMs(ms: number): string {
129154
export type WatchWaitBasis = "queued_at" | "delay_until" | "created_at";
130155

131156
/**
132-
* The wait a run has accumulated, with the ONLY label the data supports:
133-
* `queuedAt` present -> a real queue wait; a future `delayUntil` -> a schedule,
134-
* not latency; otherwise time from creation, said out loud.
157+
* The wait a run has accumulated, with the ONLY label the data supports: a
158+
* `queuedAt` that belongs to THIS attempt -> a real queue wait; a future
159+
* `delayUntil` -> a schedule, not latency; otherwise time from creation, said out
160+
* loud.
161+
*
162+
* A resumed/retried/paused run's `queuedAt` is a leftover from the first enqueue,
163+
* so it is not measured from at all: a number that isn't this attempt's queue
164+
* wait must never be worded as one, even with a flag next to it.
135165
*/
136166
export function describeRunWait(
137167
run: WatchRunRow,
@@ -140,13 +170,13 @@ export function describeRunWait(
140170
waitMs: number | null;
141171
waitBasis: WatchWaitBasis;
142172
waitLabel: string;
143-
/** False when `queuedAt` can't be read as this attempt's queue wait. */
173+
/** True only when the wait IS this attempt's queue wait. */
144174
queueWaitReliable: boolean;
145175
} {
146176
const queueWaitReliable = run.queuedAt !== null && !STALE_QUEUED_AT_STATUSES.has(run.status);
147177
const end = run.startedAt ?? now;
148178

149-
if (run.queuedAt) {
179+
if (run.queuedAt && queueWaitReliable) {
150180
const waitMs = Math.max(0, end.getTime() - run.queuedAt.getTime());
151181
return {
152182
waitMs,
@@ -165,11 +195,16 @@ export function describeRunWait(
165195
};
166196
}
167197

198+
// Either there is no `queuedAt`, or the one we have belongs to an earlier
199+
// attempt. Both fall back to the run's age, and say that's what it is.
168200
const waitMs = Math.max(0, end.getTime() - run.createdAt.getTime());
201+
const resumeOrRetry = run.queuedAt !== null;
169202
return {
170203
waitMs,
171204
waitBasis: "created_at",
172-
waitLabel: `time from creation: ${formatMs(waitMs)}`,
205+
waitLabel: resumeOrRetry
206+
? `waiting to ${run.status === "RETRYING_AFTER_FAILURE" ? "retry" : "resume"}; time from creation: ${formatMs(waitMs)}`
207+
: `time from creation: ${formatMs(waitMs)}`,
173208
queueWaitReliable,
174209
};
175210
}
@@ -256,6 +291,11 @@ export async function checkRunFinished(
256291
* backlog_drain — satisfied when the queue's current pending count is 0. A queue
257292
* that no longer exists can never drain in an observable sense, so that's
258293
* `terminal_unsatisfied`; a depth we can't read is `unavailable`, never "drained".
294+
*
295+
* A zero needs a reading that describes NOW (`current`): a stale analytics bucket
296+
* that happened to be empty says nothing about the runs queued after it, so it's
297+
* `unavailable` too. A stale NON-zero depth is still worth reporting — the queue
298+
* demonstrably wasn't empty — and is marked approximate.
259299
*/
260300
export async function checkBacklogDrain(
261301
spec: Extract<WatchSpec, { kind: "backlog_drain" }>,
@@ -277,7 +317,18 @@ export async function checkBacklogDrain(
277317
return { result: "unavailable", facts: { queue: spec.queue, reason: "depth_unavailable" } };
278318
}
279319

280-
const facts = { queue: spec.queue, depth: depth.depth, depthSource: depth.source };
320+
const facts = {
321+
queue: spec.queue,
322+
depth: depth.depth,
323+
depthSource: depth.source,
324+
depthAsOf: depth.asOf?.toISOString() ?? null,
325+
depthApproximate: !depth.current,
326+
};
327+
328+
if (depth.depth === 0 && !depth.current) {
329+
return { result: "unavailable", facts: { ...facts, reason: "depth_stale" } };
330+
}
331+
281332
return { result: depth.depth === 0 ? "satisfied" : "pending", facts };
282333
}
283334

@@ -291,9 +342,13 @@ export function normalizeErrorFingerprint(fingerprint: string): string {
291342
}
292343

293344
/**
294-
* error_recurrence — satisfied on the first occurrence strictly after the
295-
* server-set `since`. `since` is never caller-set, so the model can't backdate
296-
* the window and make a pre-existing error look like a recurrence.
345+
* error_recurrence — satisfied on the first occurrence proven to be after the
346+
* server-set `since`. `since` is never caller-set, so the model can't backdate the
347+
* window and make a pre-existing error look like a recurrence.
348+
*
349+
* The facts carry the PRECISION of what they claim (`occurredAtPrecision`,
350+
* `countApproximate`) and, when nothing recurred, when the error was last seen —
351+
* so the wake narration can't assert more than the data supports.
297352
*/
298353
export async function checkErrorRecurrence(
299354
spec: Extract<WatchSpec, { kind: "error_recurrence" }>,
@@ -305,15 +360,24 @@ export async function checkErrorRecurrence(
305360
const base = { fingerprint, since: input.since.toISOString() };
306361

307362
if (!recurrence) {
308-
return { result: "pending", facts: { ...base, countSince: 0 } };
363+
return { result: "pending", facts: { ...base, countSince: 0, lastSeenAt: null } };
364+
}
365+
366+
const lastSeenAt = recurrence.lastSeenAt?.toISOString() ?? null;
367+
368+
if (!recurrence.occurredAt) {
369+
return { result: "pending", facts: { ...base, countSince: 0, lastSeenAt } };
309370
}
310371

311372
return {
312373
result: "satisfied",
313374
facts: {
314375
...base,
315376
occurredAt: recurrence.occurredAt.toISOString(),
377+
occurredAtPrecision: recurrence.occurredAtPrecision,
316378
countSince: recurrence.countSince,
379+
countApproximate: recurrence.countApproximate,
380+
lastSeenAt,
317381
},
318382
};
319383
}

0 commit comments

Comments
 (0)