Skip to content

Commit d7f3915

Browse files
d-csclaude
andcommitted
fix(webapp): emit mollifier drainer LOG event as marker, not back-dated bar
engine.trigger rewrites the run's root span at materialisation (adopts the synth root via traceId/spanId carryover but updates start_time to "now"). A back-dated LOG event with startTime = bufferedAt landed before that root start and got clipped from the trace tree — persisted in ClickHouse but invisible to the admin viewing the page. Emit it as a zero-duration marker AT materialisation time instead, matching the [engine] QUEUED / PENDING_EXECUTING pattern. The historical window is preserved in metadata so admins can still read bufferedAt / dwellMs / attempts off the span detail pane. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
1 parent a1f6c3a commit d7f3915

2 files changed

Lines changed: 31 additions & 20 deletions

File tree

apps/webapp/app/v3/mollifier/mollifierDrainerHandler.server.ts

Lines changed: 22 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -217,23 +217,32 @@ export function createDrainerHandler(deps: {
217217
}
218218

219219
// Admin-only audit trail emitted once engine.trigger has
220-
// landed a PG row. `recordRunDebugLog` flips this to
221-
// `TaskEventKind.LOG`, which the trace view + logs download
222-
// already gate behind admin
220+
// landed a PG row. `recordRunDebugLog` flips this to the
221+
// admin-gated debug kind (TaskEventKind.LOG in the PG store /
222+
// DEBUG_EVENT in the ClickHouse store) which the trace view +
223+
// logs download already strip for non-admins
223224
// (`eventRepository.server.ts:108`,
224-
// `resources.runs.$runParam.logs.download.ts:118`). Encoding
225-
// the buffered window as `startTime` + `duration` makes the
226-
// event render at the historical instant inside the run's
227-
// existing trace — admins see "Mollifier buffered for Xms"
228-
// sitting between trigger and dequeue. Best-effort: the
229-
// helper has its own try/catch and returns a result, so it
230-
// never throws into the materialisation path. Failures are
231-
// logged but not surfaced because the customer-visible run
232-
// has already landed.
225+
// `resources.runs.$runParam.logs.download.ts:118`).
226+
//
227+
// Placement: emit as a zero-duration marker AT materialisation
228+
// time, not as a back-dated bar spanning the buffered window.
229+
// `engine.trigger` rewrites the run's root span at
230+
// materialisation (it adopts the synth root via traceId/spanId
231+
// carryover but updates start_time to "now"), so the trace
232+
// renderer treats materialisation time as t=0. A back-dated
233+
// event with startTime = bufferedAt would land before that t=0
234+
// and get clipped from the tree. Same pattern as the
235+
// `[engine] QUEUED` markers. The window itself is preserved
236+
// in metadata so admins can read it off the span detail pane.
237+
//
238+
// Best-effort: `recordRunDebugLog` has its own try/catch and
239+
// returns a result, so it never throws into the materialisation
240+
// path. Failures are logged but not surfaced because the
241+
// customer-visible run has already landed.
233242
if (triggerSucceeded) {
234243
const debugResult = await recordRunDebugLog(
235244
RunId.fromFriendlyId(input.runId),
236-
`Mollifier buffered for ${dwellMs}ms before materialising`,
245+
`Mollifier buffered ${dwellMs}ms before materialising`,
237246
{
238247
attributes: {
239248
runId: input.runId,
@@ -244,8 +253,6 @@ export function createDrainerHandler(deps: {
244253
"mollifier.attempts": input.attempts,
245254
},
246255
},
247-
startTime: input.createdAt,
248-
duration: dwellMs * 1_000_000,
249256
parentId: snapshotSpanId,
250257
}
251258
);

apps/webapp/test/mollifierDrainerHandler.test.ts

Lines changed: 9 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -497,14 +497,18 @@ describe("createDrainerHandler", () => {
497497
// Internal cuid derived from the friendlyId, mirroring what
498498
// `findRunForEventCreation` queries on.
499499
expect(callRunId).toBe("z");
500-
expect(message).toMatch(/Mollifier buffered for \d+ms/);
501-
// Encodes the historical buffered window so the trace view places
502-
// the LOG event between trigger and dequeue (not at "now").
503-
expect(options.startTime).toBe(bufferedAt);
504-
expect(options.duration).toBeGreaterThan(0);
500+
expect(message).toMatch(/Mollifier buffered \d+ms before materialising/);
501+
// Emitted as a marker at materialisation time (no `startTime` /
502+
// `duration` overrides) — engine.trigger has just rewritten the
503+
// root span's start_time to "now", so back-dating the event would
504+
// clip it off-screen in the trace renderer. The historical window
505+
// is preserved in metadata so admins can still read it.
506+
expect(options.startTime).toBeUndefined();
507+
expect(options.duration).toBeUndefined();
505508
expect(options.parentId).toBe("snapspan");
506509
expect(options.attributes.metadata["mollifier.bufferedAt"]).toBe(bufferedAt.toISOString());
507510
expect(options.attributes.metadata["mollifier.attempts"]).toBe(2);
511+
expect(options.attributes.metadata["mollifier.dwellMs"]).toBeGreaterThan(0);
508512
});
509513

510514
it("does NOT emit the admin LOG event when engine.trigger fails non-retryably", async () => {

0 commit comments

Comments
 (0)