-
-
Notifications
You must be signed in to change notification settings - Fork 1.1k
fix(webapp): reconcile trace with run lifecycle to handle ClickHouse lag #2875
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Changes from 4 commits
bfda16b
e8d84fa
b591e28
425c3b4
4b19a1f
e030cc2
4c3f0e8
4dfadb9
80c5baf
17dbcd0
960b23f
805eae7
972db5f
be43941
389e037
3052cc4
92fd9f9
c6ebc5a
27fd2db
838980c
daab67c
c743d9d
52311e7
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -6,7 +6,7 @@ import { getUsername } from "~/utils/username"; | |
| import { resolveEventRepositoryForStore } from "~/v3/eventRepository/index.server"; | ||
| import { SpanSummary } from "~/v3/eventRepository/eventRepository.types"; | ||
| import { getTaskEventStoreTableForRun } from "~/v3/taskEventStore.server"; | ||
| import { isFinalRunStatus } from "~/v3/taskStatus"; | ||
| import { isFailedRunStatus, isFinalRunStatus } from "~/v3/taskStatus"; | ||
| import { env } from "~/env.server"; | ||
|
|
||
| type Result = Awaited<ReturnType<RunPresenter["call"]>>; | ||
|
|
@@ -211,49 +211,47 @@ export class RunPresenter { | |
| let totalDuration = tree?.data.duration ?? 0; | ||
| const events = tree | ||
| ? flattenTree(tree).map((n) => { | ||
| const offset = millisecondsToNanoseconds( | ||
| n.data.startTime.getTime() - treeRootStartTimeMs | ||
| ); | ||
| //only let non-debug events extend the total duration | ||
| if (!n.data.isDebug) { | ||
| totalDuration = Math.max(totalDuration, offset + n.data.duration); | ||
| } | ||
| return { | ||
| ...n, | ||
| data: { | ||
| ...n.data, | ||
| timelineEvents: createTimelineSpanEventsFromSpanEvents( | ||
| n.data.events, | ||
| user?.admin ?? false, | ||
| treeRootStartTimeMs | ||
| ), | ||
| //set partial nodes to null duration | ||
| duration: n.data.isPartial ? null : n.data.duration, | ||
| offset, | ||
| isRoot: n.id === traceSummary.rootSpan.id, | ||
| }, | ||
| }; | ||
| }) | ||
| const offset = millisecondsToNanoseconds( | ||
| n.data.startTime.getTime() - treeRootStartTimeMs | ||
| ); | ||
| //only let non-debug events extend the total duration | ||
| if (!n.data.isDebug) { | ||
| totalDuration = Math.max(totalDuration, offset + n.data.duration); | ||
| } | ||
| return { | ||
| ...n, | ||
| data: { | ||
| ...n.data, | ||
| timelineEvents: createTimelineSpanEventsFromSpanEvents( | ||
| n.data.events, | ||
| user?.admin ?? false, | ||
| treeRootStartTimeMs | ||
| ), | ||
| //set partial nodes to null duration | ||
| duration: n.data.isPartial ? null : n.data.duration, | ||
| offset, | ||
| isRoot: n.id === traceSummary.rootSpan.id, | ||
| }, | ||
| }; | ||
| }) | ||
| : []; | ||
|
|
||
| //total duration should be a minimum of 1ms | ||
| totalDuration = Math.max(totalDuration, millisecondsToNanoseconds(1)); | ||
|
|
||
| let rootSpanStatus: "executing" | "completed" | "failed" = "executing"; | ||
| if (events[0]) { | ||
| if (events[0].data.isError) { | ||
| rootSpanStatus = "failed"; | ||
| } else if (!events[0].data.isPartial) { | ||
| rootSpanStatus = "completed"; | ||
| } | ||
| } | ||
| const reconciled = reconcileTraceWithRunLifecycle( | ||
| runData, | ||
| traceSummary.rootSpan.id, | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 🔴 Reconciliation fails for child task runs due to incorrect root span ID comparison The reconciliation logic does not update the root span's Click to expandRoot CauseIn const reconciled = reconcileTraceWithRunLifecycle(
runData,
traceSummary.rootSpan.id, // This is the TRACE's root span
events,
totalDuration
);However, the const tree = createTreeFromFlatItems(traceSummary.spans, run.spanId);This means In the reconciliation function (
|
||
| events, | ||
| totalDuration | ||
| ); | ||
|
|
||
| return { | ||
| run: runData, | ||
| trace: { | ||
| rootSpanStatus, | ||
| events: events, | ||
| duration: totalDuration, | ||
| rootSpanStatus: reconciled.rootSpanStatus, | ||
| events: reconciled.events, | ||
| duration: reconciled.totalDuration, | ||
| rootStartedAt: tree?.data.startTime, | ||
| startedAt: run.startedAt, | ||
| queuedDuration: run.startedAt | ||
|
|
@@ -265,3 +263,67 @@ export class RunPresenter { | |
| }; | ||
| } | ||
| } | ||
|
|
||
| // NOTE: Clickhouse trace ingestion is eventually consistent. | ||
| // When a run is marked finished in Postgres, we reconcile the | ||
| // root span to reflect completion even if telemetry is still partial. | ||
| // This is a deliberate UI-layer tradeoff to prevent stale or "stuck" | ||
| // run states in the dashboard. | ||
| export function reconcileTraceWithRunLifecycle( | ||
| runData: { | ||
| isFinished: boolean; | ||
| status: Run["status"]; | ||
| createdAt: Date; | ||
| completedAt: Date | null; | ||
| rootTaskRun: { createdAt: Date } | null; | ||
| }, | ||
coderabbitai[bot] marked this conversation as resolved.
Outdated
Show resolved
Hide resolved
|
||
| rootSpanId: string, | ||
| events: RunEvent[], | ||
| totalDuration: number | ||
| ): { | ||
| events: RunEvent[]; | ||
| totalDuration: number; | ||
| rootSpanStatus: "executing" | "completed" | "failed"; | ||
| } { | ||
| const currentStatus: "executing" | "completed" | "failed" = events[0] | ||
| ? events[0].data.isError | ||
| ? "failed" | ||
| : !events[0].data.isPartial | ||
| ? "completed" | ||
| : "executing" | ||
| : "executing"; | ||
coderabbitai[bot] marked this conversation as resolved.
Outdated
Show resolved
Hide resolved
|
||
|
|
||
| if (!runData.isFinished) { | ||
| return { events, totalDuration, rootSpanStatus: currentStatus }; | ||
| } | ||
|
|
||
| const postgresRunDuration = runData.completedAt | ||
| ? millisecondsToNanoseconds( | ||
| runData.completedAt.getTime() - | ||
| (runData.rootTaskRun?.createdAt ?? runData.createdAt).getTime() | ||
| ) | ||
| : 0; | ||
|
|
||
| const updatedTotalDuration = Math.max(totalDuration, postgresRunDuration); | ||
|
|
||
| const updatedEvents = events.map((e) => { | ||
| if (e.id === rootSpanId && e.data.isPartial) { | ||
| return { | ||
| ...e, | ||
| data: { | ||
| ...e.data, | ||
| isPartial: false, | ||
| duration: Math.max(e.data.duration ?? 0, postgresRunDuration), | ||
| isError: isFailedRunStatus(runData.status), | ||
| }, | ||
| }; | ||
| } | ||
| return e; | ||
| }); | ||
|
|
||
| return { | ||
| events: updatedEvents, | ||
| totalDuration: updatedTotalDuration, | ||
| rootSpanStatus: isFailedRunStatus(runData.status) ? "failed" : "completed", | ||
| }; | ||
| } | ||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,141 @@ | ||
| import { vi, describe, it, expect } from "vitest"; | ||
|
||
|
|
||
| vi.mock("../app/env.server", () => ({ | ||
| env: { | ||
| MAXIMUM_LIVE_RELOADING_EVENTS: 1000, | ||
| }, | ||
| })); | ||
|
|
||
| vi.mock("../app/db.server", () => ({ | ||
| prisma: {}, | ||
| $replica: {}, | ||
| $transaction: vi.fn(), | ||
| })); | ||
|
|
||
| vi.mock("../app/v3/eventRepository/index.server", () => ({ | ||
| resolveEventRepositoryForStore: vi.fn(), | ||
| })); | ||
|
|
||
| vi.mock("../app/v3/taskEventStore.server", () => ({ | ||
| getTaskEventStoreTableForRun: vi.fn(), | ||
| })); | ||
|
|
||
| vi.mock("../app/utils/username", () => ({ | ||
| getUsername: vi.fn(), | ||
| })); | ||
|
|
||
| import { reconcileTraceWithRunLifecycle } from "../app/presenters/v3/RunPresenter.server"; | ||
| import { millisecondsToNanoseconds } from "@trigger.dev/core/v3"; | ||
|
|
||
| describe("reconcileTraceWithRunLifecycle", () => { | ||
| const rootSpanId = "root-span-id"; | ||
| const createdAt = new Date("2024-01-01T00:00:00Z"); | ||
| const completedAt = new Date("2024-01-01T00:00:05Z"); | ||
|
|
||
| const runData: any = { | ||
| isFinished: true, | ||
| status: "COMPLETED_SUCCESSFULLY", | ||
| createdAt, | ||
| completedAt, | ||
| rootTaskRun: null, | ||
| }; | ||
|
|
||
| const initialEvents = [ | ||
| { | ||
| id: rootSpanId, | ||
| data: { | ||
| isPartial: true, | ||
| duration: millisecondsToNanoseconds(1000), // 1s, less than the 5s run duration | ||
| isError: false, | ||
| }, | ||
| }, | ||
| { | ||
| id: "child-span-id", | ||
| data: { | ||
| isPartial: false, | ||
| duration: millisecondsToNanoseconds(500), | ||
| isError: false, | ||
| }, | ||
| }, | ||
| ]; | ||
|
|
||
| it("should reconcile a finished run with lagging partial telemetry", () => { | ||
| const totalDuration = millisecondsToNanoseconds(1000); | ||
| const result = reconcileTraceWithRunLifecycle(runData, rootSpanId, initialEvents as any, totalDuration); | ||
|
|
||
| expect(result.rootSpanStatus).toBe("completed"); | ||
|
|
||
| const rootEvent = result.events.find((e: any) => e.id === rootSpanId); | ||
| expect(rootEvent?.data.isPartial).toBe(false); | ||
| // 5s duration = 5000ms | ||
| expect(rootEvent?.data.duration).toBeGreaterThanOrEqual(millisecondsToNanoseconds(5000)); | ||
| expect(result.totalDuration).toBeGreaterThanOrEqual(millisecondsToNanoseconds(5000)); | ||
| }); | ||
|
|
||
| it("should not override duration if Clickhouse already has a longer finished duration", () => { | ||
| const longDuration = millisecondsToNanoseconds(10000); | ||
| const finishedEvents = [ | ||
| { | ||
| id: rootSpanId, | ||
| data: { | ||
| isPartial: false, | ||
| duration: longDuration, | ||
| isError: false, | ||
| }, | ||
| }, | ||
| ]; | ||
|
|
||
| const result = reconcileTraceWithRunLifecycle(runData, rootSpanId, finishedEvents as any, longDuration); | ||
|
|
||
| const rootEvent = result.events.find((e: any) => e.id === rootSpanId); | ||
| expect(rootEvent?.data.duration).toBe(longDuration); | ||
| expect(rootEvent?.data.isPartial).toBe(false); | ||
| expect(result.totalDuration).toBe(longDuration); | ||
| }); | ||
|
|
||
| it("should handle unfinished runs without modification", () => { | ||
| const unfinishedRun = { ...runData, isFinished: false, completedAt: null }; | ||
| const totalDuration = millisecondsToNanoseconds(1000); | ||
| const result = reconcileTraceWithRunLifecycle(unfinishedRun, rootSpanId, initialEvents as any, totalDuration); | ||
|
|
||
| expect(result.rootSpanStatus).toBe("executing"); | ||
|
|
||
| const rootEvent = result.events.find((e: any) => e.id === rootSpanId); | ||
| expect(rootEvent?.data.isPartial).toBe(true); | ||
| expect(rootEvent?.data.duration).toBe(millisecondsToNanoseconds(1000)); | ||
| }); | ||
|
|
||
| it("should reconcile failed runs correctly", () => { | ||
| const failedRun = { ...runData, status: "COMPLETED_WITH_ERRORS" }; | ||
| const result = reconcileTraceWithRunLifecycle(failedRun, rootSpanId, initialEvents as any, millisecondsToNanoseconds(1000)); | ||
|
|
||
| expect(result.rootSpanStatus).toBe("failed"); | ||
| const rootEvent = result.events.find((e: any) => e.id === rootSpanId); | ||
| expect(rootEvent?.data.isError).toBe(true); | ||
| expect(rootEvent?.data.isPartial).toBe(false); | ||
| }); | ||
|
|
||
| it("should use rootTaskRun createdAt if available for duration calculation", () => { | ||
| const rootTaskCreatedAt = new Date("2023-12-31T23:59:50Z"); // 10s before run.createdAt | ||
| const runDataWithRoot: any = { | ||
| ...runData, | ||
| rootTaskRun: { createdAt: rootTaskCreatedAt }, | ||
| }; | ||
|
|
||
| const result = reconcileTraceWithRunLifecycle(runDataWithRoot, rootSpanId, initialEvents as any, millisecondsToNanoseconds(1000)); | ||
|
|
||
| // Duration should be from 23:59:50 to 00:00:05 = 15s | ||
| const rootEvent = result.events.find((e: any) => e.id === rootSpanId); | ||
| expect(rootEvent?.data.duration).toBeGreaterThanOrEqual(millisecondsToNanoseconds(15000)); | ||
| expect(result.totalDuration).toBeGreaterThanOrEqual(millisecondsToNanoseconds(15000)); | ||
| }); | ||
|
|
||
| it("should handle missing root span gracefully", () => { | ||
| const result = reconcileTraceWithRunLifecycle(runData, "non-existent-id", initialEvents as any, millisecondsToNanoseconds(1000)); | ||
|
|
||
| expect(result.rootSpanStatus).toBe("completed"); | ||
| expect(result.events).toEqual(initialEvents); | ||
| // totalDuration should still be updated to postgres duration even if root span is missing from events list | ||
| expect(result.totalDuration).toBeGreaterThanOrEqual(millisecondsToNanoseconds(5000)); | ||
| }); | ||
| }); | ||
Uh oh!
There was an error while loading. Please reload this page.