From d9dab2da899db797b3cc6dd58f0904c5147013f2 Mon Sep 17 00:00:00 2001 From: Codex Date: Sat, 4 Jul 2026 16:13:12 +0000 Subject: [PATCH] fix: preserve branch follower stage intervals --- scripts/native/cicd/native-job.mjs | 6 +- scripts/src/cicd-branch-follower.ts | 109 +---------------- scripts/src/cicd-native.ts | 2 + scripts/src/cicd-render.ts | 8 +- scripts/src/cicd-timing-attribution.ts | 163 +++++++++++++++++++++++++ scripts/src/cicd-timings.ts | 60 +++++---- scripts/src/cicd-types.ts | 4 + 7 files changed, 224 insertions(+), 128 deletions(-) create mode 100644 scripts/src/cicd-timing-attribution.ts diff --git a/scripts/native/cicd/native-job.mjs b/scripts/native/cicd/native-job.mjs index 04484eff..1df5bbd5 100644 --- a/scripts/native/cicd/native-job.mjs +++ b/scripts/native/cicd/native-job.mjs @@ -106,6 +106,7 @@ if (existing) { } const startedAt = Date.now(); +const startedAtIso = new Date(startedAt).toISOString(); const deadline = startedAt + timeoutSeconds * 1000; let polls = 0; let latest = await getJob(); @@ -123,6 +124,7 @@ const failed = condition(latest, "Failed"); const logs = await logsTail(); const summary = parseLastJsonSummary(logs); const timedOut = !complete && !failed; +const finishedAt = Date.now(); const output = { ok: Boolean(complete) && !timedOut, completed: Boolean(complete), @@ -134,7 +136,9 @@ const output = { jobName, namespace, polls, - elapsedMs: Date.now() - startedAt, + elapsedMs: finishedAt - startedAt, + startedAt: startedAtIso, + finishedAt: new Date(finishedAt).toISOString(), conditionReason: complete?.reason || failed?.reason || null, conditionMessage: complete?.message || failed?.message || null, logsTail: logs || null, diff --git a/scripts/src/cicd-branch-follower.ts b/scripts/src/cicd-branch-follower.ts index 4e3fbedd..fcb450b8 100644 --- a/scripts/src/cicd-branch-follower.ts +++ b/scripts/src/cicd-branch-follower.ts @@ -37,6 +37,7 @@ import { buildCicdHelp } from "./cicd-help"; import { attachReconcileTimeline, compactReconcileTimeline, finishReconcileStep, finishReconcileTimeline, startReconcileStep, startReconcileTimeline } from "./cicd-reconcile-timeline"; import { orderFollowersForControllerCloseout, shouldYieldAfterAutomaticTrigger } from "./cicd-reconcile-scheduler"; import { buildFollowerTimings, compactListTimings, compactTimings, storedFollowerTimingsForStatus, timingPerformanceSummary } from "./cicd-timings"; +import { timingAttributionSummary } from "./cicd-timing-attribution"; import type { AdapterSummary, BranchFollowerAction, BranchFollowerDebugStep, BranchFollowerGate, BranchFollowerPhase, BranchFollowerRegistry, ControllerSpec, FollowerSpec, FollowerState, K8sFollowerStateRead, K8sStateRead, NativeCloseoutWaitResult, NativeK8sJobResult, NativeStatusSpec, NativeWorkloadSpec, OutputMode, ParsedOptions, TriggerResult } from "./cicd-types"; import { arrayField, @@ -1843,6 +1844,8 @@ async function readAdapterStatus(registry: BranchFollowerRegistry, follower: Fol const sourceSyncDetail = sourceSync === null || sourceSync.result.ok ? null : redactText(tailText(sourceSync.result.conditionMessage ?? sourceSync.result.logsTail ?? "unknown", 800)); const sourceSyncError = sourceSyncDetail === null ? null : `native source sync failed: ${sourceSyncDetail}`; const bundle = readNativeObjectBundle(registry, follower, options, remainingSeconds(startedAt, timeoutSeconds), runKubeScript); + const bundleFinishedMs = Date.now(); + const bundleStartedMs = Math.max(startedAt, bundleFinishedMs - Math.max(0, bundle.elapsedMs)); const observedSha = sourceSyncError === null ? stringOrNull(bundle.source?.commit) : null; const runtimeTargetSha = runtimeTargetShaFromWorkloads(follower.nativeStatus.runtime, bundle.workloads); const pipelineRunName = stringOrNull(asOptionalRecord(bundle.pipelineRun?.metadata)?.name) ?? expectedPipelineRunName(follower, observedSha); @@ -1902,7 +1905,7 @@ async function readAdapterStatus(registry: BranchFollowerRegistry, follower: Fol planArtifacts: bundle.planArtifacts, argo: nativeArgoSummary(bundle.argoApplication), runtime: nativeRuntimeSummary(follower.nativeStatus.runtime, bundle.workloads, observedSha), - timings: { statusRead: { elapsedMs: bundle.elapsedMs, budgetSeconds: timeoutSeconds } }, + timings: { statusRead: { elapsedMs: bundle.elapsedMs, budgetSeconds: timeoutSeconds, startedAt: new Date(bundleStartedMs).toISOString(), finishedAt: new Date(bundleFinishedMs).toISOString() } }, errors, statusAuthority: "k8s-native", parsedDownstreamCliOutput: false, @@ -2632,9 +2635,11 @@ function nativeGateTimingSummary(payload: Record | null, timing statusReadSeconds: secondsFromMsValue(numberOrNull(statusRead?.elapsedMs)), gitMirrorSyncSeconds: secondsFromMsValue(numberOrNull(sourceSync?.elapsedMs)), pipelineRunSeconds: numberOrNull(tekton?.durationSeconds), + pipelineRunName: stringOrNull(tekton?.name), pipelineRunStartedAt: stringOrNull(tekton?.startTime), pipelineRunFinishedAt: stringOrNull(tekton?.completionTime), argoOperationSeconds: numberOrNull(argo?.operationDurationSeconds), + argoApplication: stringOrNull(argo?.name), argoOperationStartedAt: stringOrNull(argo?.operationStartedAt), argoOperationFinishedAt: stringOrNull(argo?.operationFinishedAt), argoIncludedInStoredTotal: argoStage?.seconds !== null && argoStage?.source === "argocd", @@ -2644,108 +2649,6 @@ function nativeGateTimingSummary(payload: Record | null, timing }; } -function timingAttributionSummary(timings: FollowerState["timings"], nativeGate: Record): Record { - const totalStartedMs = timestampMs(timings.startedAt); - const totalFinishedMs = timestampMs(timings.finishedAt); - const totalSeconds = timings.totalSeconds; - if (totalSeconds === null || totalStartedMs === null || totalFinishedMs === null || totalFinishedMs < totalStartedMs) { - return { - status: "unknown", - source: "stored-total-vs-native-intervals", - totalSeconds, - knownIntervalCoverageSeconds: null, - unknownWallClockSeconds: null, - reason: "stored total range is missing or invalid; old wall-clock attribution cannot be reconstructed", - }; - } - const intervals = [ - timingIntervalOverlap("pipeline", "tekton", nativeGate.pipelineRunStartedAt, nativeGate.pipelineRunFinishedAt, totalStartedMs, totalFinishedMs), - timingIntervalOverlap("argo", "argocd", nativeGate.argoOperationStartedAt, nativeGate.argoOperationFinishedAt, totalStartedMs, totalFinishedMs), - ].filter((item): item is Record => item !== null); - const coverageSeconds = mergedIntervalCoverageSeconds(intervals); - const unknownSeconds = roundSeconds(Math.max(0, totalSeconds - coverageSeconds)); - const missingHistoricalIntervals = timings.stages.some((stage) => stage.seconds !== null); - return { - status: unknownSeconds > 0 ? "partial" : "covered", - source: "stored-total-vs-native-intervals", - totalSeconds, - totalStartedAt: timings.startedAt, - totalFinishedAt: timings.finishedAt, - knownIntervalCoverageSeconds: coverageSeconds, - unknownWallClockSeconds: unknownSeconds, - intervalCount: intervals.length, - intervals: intervals.map(({ startMs: _startMs, endMs: _endMs, overlapStartMs: _overlapStartMs, overlapEndMs: _overlapEndMs, ...item }) => item), - reason: unknownSeconds > 0 - ? missingHistoricalIntervals - ? "stored state lacks historical per-stage intervals for the remaining wall-clock; do not infer wait/idle from current native objects" - : "no stored historical native intervals overlap the total range; old wall-clock attribution cannot be reconstructed" - : null, - }; -} - -function timingIntervalOverlap(stage: string, source: string, startedAtValue: unknown, finishedAtValue: unknown, totalStartedMs: number, totalFinishedMs: number): Record | null { - const startedAt = stringOrNull(startedAtValue); - const finishedAt = stringOrNull(finishedAtValue); - const startMs = timestampMs(startedAt); - const endMs = timestampMs(finishedAt); - if (startMs === null || endMs === null || endMs < startMs) return null; - const overlapStartMs = Math.max(startMs, totalStartedMs); - const overlapEndMs = Math.min(endMs, totalFinishedMs); - const overlapSeconds = overlapEndMs > overlapStartMs ? roundSeconds((overlapEndMs - overlapStartMs) / 1000) : 0; - return { - stage, - source, - startedAt, - finishedAt, - overlapSeconds, - inStoredTotal: overlapSeconds > 0, - startMs, - endMs, - overlapStartMs, - overlapEndMs, - }; -} - -function mergedIntervalCoverageSeconds(intervals: Record[]): number { - const ranges = intervals - .map((item) => ({ - startMs: numberOrNull(item.overlapStartMs), - endMs: numberOrNull(item.overlapEndMs), - overlapSeconds: numberOrNull(item.overlapSeconds), - })) - .filter((item): item is { startMs: number; endMs: number; overlapSeconds: number } => item.startMs !== null && item.endMs !== null && item.overlapSeconds !== null && item.overlapSeconds > 0) - .sort((a, b) => a.startMs - b.startMs); - let coveredMs = 0; - let currentStart: number | null = null; - let currentEnd: number | null = null; - for (const range of ranges) { - if (currentStart === null || currentEnd === null) { - currentStart = range.startMs; - currentEnd = range.endMs; - continue; - } - if (range.startMs <= currentEnd) { - currentEnd = Math.max(currentEnd, range.endMs); - continue; - } - coveredMs += currentEnd - currentStart; - currentStart = range.startMs; - currentEnd = range.endMs; - } - if (currentStart !== null && currentEnd !== null) coveredMs += currentEnd - currentStart; - return roundSeconds(coveredMs / 1000); -} - -function timestampMs(value: string | null): number | null { - if (value === null) return null; - const parsed = Date.parse(value); - return Number.isFinite(parsed) ? parsed : null; -} - -function roundSeconds(value: number): number { - return Math.round(value * 10) / 10; -} - function followerNextCommands(follower: FollowerSpec): Record { const next: Record = { status: `bun scripts/cli.ts cicd branch-follower status --follower ${follower.id}`, diff --git a/scripts/src/cicd-native.ts b/scripts/src/cicd-native.ts index acd407be..f1da38c1 100644 --- a/scripts/src/cicd-native.ts +++ b/scripts/src/cicd-native.ts @@ -52,6 +52,8 @@ export function runNativeK8sJob(namespace: string, jobName: string, manifest: Re namespace, polls: numberOrNull(parsed?.polls) ?? 0, elapsedMs: numberOrNull(parsed?.elapsedMs) ?? 0, + startedAt: stringOrNull(parsed?.startedAt), + finishedAt: stringOrNull(parsed?.finishedAt), logsTail: stringOrNull(parsed?.logsTail), summary: asOptionalRecord(parsed?.summary), conditionReason: stringOrNull(parsed?.conditionReason), diff --git a/scripts/src/cicd-render.ts b/scripts/src/cicd-render.ts index 3273da76..3ee6d3f5 100644 --- a/scripts/src/cicd-render.ts +++ b/scripts/src/cicd-render.ts @@ -127,7 +127,7 @@ function renderStatusHuman(payload: Record, _options: ParsedOpt liveRefreshRows.length === 0 ? "" : `\nLIVE REFRESH\n${table(["MODE", "REQUESTED", "EXECUTED", "JOB", "ELAPSED", "IN_TOTAL"], liveRefreshRows)}`, "", table(["FOLLOWER", "PHASE", "ADAPTER", "OBSERVED", "TARGET", "TRIGGERED", "SUCCEEDED", "IN_FLIGHT", "BUDGET", "MESSAGE"], rows), - timingRows.length === 0 ? "" : `\nSTAGE TIMINGS\n${table(["FOLLOWER", "STAGE", "STATUS", "SECONDS", "BUDGET", "OBJECT"], timingRows)}`, + timingRows.length === 0 ? "" : `\nSTAGE TIMINGS\n${table(["FOLLOWER", "STAGE", "STATUS", "SECONDS", "BUDGET", "STARTED", "FINISHED", "OBJECT"], timingRows)}`, timingContextRows.length === 0 ? "" : `\nTIMING CONTEXT\n${table(["FOLLOWER", "CONTEXT", "SOURCE", "SECONDS", "STARTED", "FINISHED", "IN_TOTAL"], timingContextRows)}`, performanceRows.length === 0 ? "" : `\nSLOW STAGES\n${table(["FOLLOWER", "STAGE", "STATUS", "SECONDS", "SOURCE", "OBJECT"], performanceRows)}`, evidenceRows.length === 0 ? "" : `\nEVIDENCE\n${table(["FOLLOWER", "TYPE", "STATUS", "DETAIL", "OBJECT"], evidenceRows)}`, @@ -188,7 +188,7 @@ function renderRunOnceHuman(payload: Record): string { `CI/CD BRANCH-FOLLOWER RUN-ONCE (${payload.ok === false ? "blocked" : payload.dryRun === true ? "dry-run" : "ok"})`, "", table(["FOLLOWER", "PHASE", "OBSERVED", "TARGET", "TRIGGERED", "IN_FLIGHT", "DECISION"], rows), - timingRows.length === 0 ? "" : `\nSTAGE TIMINGS\n${table(["FOLLOWER", "STAGE", "STATUS", "SECONDS", "BUDGET", "OBJECT"], timingRows)}`, + timingRows.length === 0 ? "" : `\nSTAGE TIMINGS\n${table(["FOLLOWER", "STAGE", "STATUS", "SECONDS", "BUDGET", "STARTED", "FINISHED", "OBJECT"], timingRows)}`, reconcileRows.length === 0 ? "" : `\nRECONCILE TIMELINE\n${table(["FOLLOWER", "STEP", "STATUS", "SECONDS", "STARTED", "OBJECT"], reconcileRows)}`, writeRows.length === 0 ? "" : `\nSTATE WRITES\n${table(["FOLLOWER", "STATUS", "BEFORE_RV", "AFTER_RV", "PRESERVED", "EXIT", "MESSAGE"], writeRows)}`, "", @@ -237,6 +237,8 @@ function timingRowsForFollower(item: Record): unknown[][] { stringOrNull(timings.totalStatus) ?? "unknown", formatSeconds(numberOrNull(timings.totalSeconds)), formatSeconds(budget), + stringOrNull(timings.startedAt) ?? "-", + stringOrNull(timings.finishedAt) ?? "-", [stringOrNull(timings.totalSource), shortSha(stringOrNull(timings.sourceCommit))].filter((value) => value !== null && value !== "-").join(":") || "-", ]]; for (const stage of arrayRecords(timings.stages)) { @@ -246,6 +248,8 @@ function timingRowsForFollower(item: Record): unknown[][] { stage.status, formatSeconds(numberOrNull(stage.seconds)), formatSeconds(numberOrNull(stage.budgetSeconds)), + stringOrNull(stage.startedAt) ?? "-", + stringOrNull(stage.finishedAt) ?? "-", stringOrNull(stage.object) ?? "-", ]); } diff --git a/scripts/src/cicd-timing-attribution.ts b/scripts/src/cicd-timing-attribution.ts new file mode 100644 index 00000000..09680e79 --- /dev/null +++ b/scripts/src/cicd-timing-attribution.ts @@ -0,0 +1,163 @@ +// SPEC: PJ2026-01060703 CI/CD branch follower timing attribution. +// Responsibility: derive bounded wall-clock attribution from stored totals and stage/native intervals. +import type { FollowerState, StageTiming } from "./cicd-types"; + +export function timingAttributionSummary(timings: FollowerState["timings"], nativeGate: Record): Record { + const totalStartedMs = timestampMs(timings.startedAt); + const totalFinishedMs = timestampMs(timings.finishedAt); + const totalSeconds = timings.totalSeconds; + if (totalSeconds === null || totalStartedMs === null || totalFinishedMs === null || totalFinishedMs < totalStartedMs) { + return { + status: "unknown", + source: "stored-total-vs-stage-intervals", + totalSeconds, + knownIntervalCoverageSeconds: null, + unknownWallClockSeconds: null, + missingIntervalStages: [], + reason: "stored total range is missing or invalid; old wall-clock attribution cannot be reconstructed", + }; + } + const stageIntervals = timings.stages + .map((stage) => timingIntervalOverlap(stage.stage, stage.source, stage.object, stage.startedAt, stage.finishedAt, totalStartedMs, totalFinishedMs)) + .filter((item): item is TimingInterval => item !== null); + const nativeIntervals = [ + timingIntervalOverlap("pipelinerun", "tekton-native-gate", String(nativeGate.pipelineRunObject ?? nativeGate.pipelineRunName ?? ""), nativeGate.pipelineRunStartedAt, nativeGate.pipelineRunFinishedAt, totalStartedMs, totalFinishedMs), + timingIntervalOverlap("argo", "argocd-native-gate", String(nativeGate.argoApplication ?? ""), nativeGate.argoOperationStartedAt, nativeGate.argoOperationFinishedAt, totalStartedMs, totalFinishedMs), + ].filter((item): item is TimingInterval => item !== null); + const intervals = dedupeIntervals([...stageIntervals, ...nativeIntervals]); + const coverageSeconds = mergedIntervalCoverageSeconds(intervals); + const unknownSeconds = roundSeconds(Math.max(0, totalSeconds - coverageSeconds)); + const missingIntervalCount = countMissingStageIntervals(timings.stages); + const missingIntervalStages = missingStageIntervals(timings.stages); + return { + status: unknownSeconds > 0 ? "partial" : "covered", + source: "stored-total-vs-stage-intervals", + totalSeconds, + totalStartedAt: timings.startedAt, + totalFinishedAt: timings.finishedAt, + knownIntervalCoverageSeconds: coverageSeconds, + unknownWallClockSeconds: unknownSeconds, + intervalCount: intervals.length, + stageIntervalCount: stageIntervals.length, + nativeIntervalCount: nativeIntervals.length, + excludedIntervalCount: intervals.filter((item) => !item.inStoredTotal).length, + missingIntervalCount, + missingIntervalReason: missingIntervalCount > 0 ? "missing-startedAt-or-finishedAt" : null, + missingIntervalStages, + intervals: intervals + .filter((item) => item.inStoredTotal) + .map(({ startMs: _startMs, endMs: _endMs, overlapStartMs: _overlapStartMs, overlapEndMs: _overlapEndMs, ...item }) => item), + reason: unknownSeconds > 0 + ? missingIntervalCount > 0 + ? "some timed stages lack startedAt/finishedAt; remaining wall-clock must stay unknown until future state records those intervals" + : "no stored historical stage intervals cover the remaining wall-clock; old data cannot be reconstructed" + : null, + }; +} + +type TimingInterval = { + stage: string; + source: string; + object: string | null; + startedAt: string; + finishedAt: string; + overlapSeconds: number; + inStoredTotal: boolean; + startMs: number; + endMs: number; + overlapStartMs: number; + overlapEndMs: number; +}; + +function timingIntervalOverlap(stage: string, source: string, object: unknown, startedAtValue: unknown, finishedAtValue: unknown, totalStartedMs: number, totalFinishedMs: number): TimingInterval | null { + const startedAt = stringOrNull(startedAtValue); + const finishedAt = stringOrNull(finishedAtValue); + const startMs = timestampMs(startedAt); + const endMs = timestampMs(finishedAt); + if (startedAt === null || finishedAt === null || startMs === null || endMs === null || endMs < startMs) return null; + const overlapStartMs = Math.max(startMs, totalStartedMs); + const overlapEndMs = Math.min(endMs, totalFinishedMs); + const overlapSeconds = overlapEndMs > overlapStartMs ? roundSeconds((overlapEndMs - overlapStartMs) / 1000) : 0; + return { + stage, + source, + object: stringOrNull(object), + startedAt, + finishedAt, + overlapSeconds, + inStoredTotal: overlapSeconds > 0, + startMs, + endMs, + overlapStartMs, + overlapEndMs, + }; +} + +function missingStageIntervals(stages: readonly StageTiming[]): Record[] { + return stages + .filter((stage) => stage.seconds !== null && (timestampMs(stage.startedAt ?? null) === null || timestampMs(stage.finishedAt ?? null) === null)) + .slice(0, 3) + .map((stage) => { + const row: Record = { + stage: stage.stage, + source: stage.source, + seconds: stage.seconds, + }; + if (stage.object !== null) row.object = stage.object; + return row; + }); +} + +function countMissingStageIntervals(stages: readonly StageTiming[]): number { + return stages.filter((stage) => stage.seconds !== null && (timestampMs(stage.startedAt ?? null) === null || timestampMs(stage.finishedAt ?? null) === null)).length; +} + +function dedupeIntervals(intervals: TimingInterval[]): TimingInterval[] { + const byKey = new Map(); + for (const interval of intervals) { + const key = `${interval.stage}\t${interval.source}\t${interval.startedAt}\t${interval.finishedAt}`; + const previous = byKey.get(key); + if (previous === undefined || previous.inStoredTotal === false && interval.inStoredTotal === true) byKey.set(key, interval); + } + return [...byKey.values()]; +} + +function mergedIntervalCoverageSeconds(intervals: TimingInterval[]): number { + const ranges = intervals + .filter((item) => item.overlapSeconds > 0) + .map((item) => ({ startMs: item.overlapStartMs, endMs: item.overlapEndMs })) + .sort((a, b) => a.startMs - b.startMs); + let coveredMs = 0; + let currentStart: number | null = null; + let currentEnd: number | null = null; + for (const range of ranges) { + if (currentStart === null || currentEnd === null) { + currentStart = range.startMs; + currentEnd = range.endMs; + continue; + } + if (range.startMs <= currentEnd) { + currentEnd = Math.max(currentEnd, range.endMs); + continue; + } + coveredMs += currentEnd - currentStart; + currentStart = range.startMs; + currentEnd = range.endMs; + } + if (currentStart !== null && currentEnd !== null) coveredMs += currentEnd - currentStart; + return roundSeconds(coveredMs / 1000); +} + +function timestampMs(value: string | null): number | null { + if (value === null) return null; + const parsed = Date.parse(value); + return Number.isFinite(parsed) ? parsed : null; +} + +function roundSeconds(value: number): number { + return Math.round(value * 10) / 10; +} + +function stringOrNull(value: unknown): string | null { + return typeof value === "string" && value.length > 0 ? value : null; +} diff --git a/scripts/src/cicd-timings.ts b/scripts/src/cicd-timings.ts index c1c7def6..01593908 100644 --- a/scripts/src/cicd-timings.ts +++ b/scripts/src/cicd-timings.ts @@ -73,14 +73,7 @@ export function compactTimings(timings: FollowerState["timings"]): FollowerState startedAt: timings.startedAt, finishedAt: timings.finishedAt, overBudget: timings.overBudget, - stages: timings.stages.slice(0, 24).map((stage) => ({ - stage: stage.stage, - status: stage.status, - seconds: stage.seconds, - budgetSeconds: stage.budgetSeconds, - source: stage.source, - object: stage.object, - })), + stages: timings.stages.slice(0, 24).map((stage) => compactStageTiming(stage, true)), }; } @@ -94,11 +87,7 @@ export function compactListTimings(timings: FollowerState["timings"]): Record ({ - stage: stage.stage, - status: stage.status, - seconds: stage.seconds, - })), + stages: timings.stages.slice(0, 4).map((stage) => compactListStageTiming(stage)), }; } @@ -141,6 +130,31 @@ function noopStoredTotalFinishOverride( return new Date().toISOString(); } +function compactStageTiming(stage: StageTiming, includeDetail: boolean): StageTiming { + const row: StageTiming = { + stage: stage.stage, + status: stage.status, + seconds: stage.seconds, + budgetSeconds: includeDetail ? stage.budgetSeconds : null, + source: includeDetail ? stage.source : "", + object: includeDetail ? stage.object : null, + }; + if (stage.startedAt !== null && stage.startedAt !== undefined) row.startedAt = stage.startedAt; + if (stage.finishedAt !== null && stage.finishedAt !== undefined) row.finishedAt = stage.finishedAt; + return row; +} + +function compactListStageTiming(stage: StageTiming): Record { + const row: Record = { + stage: stage.stage, + status: stage.status, + seconds: stage.seconds, + }; + if (stage.startedAt !== null && stage.startedAt !== undefined) row.startedAt = stage.startedAt; + if (stage.finishedAt !== null && stage.finishedAt !== undefined) row.finishedAt = stage.finishedAt; + return row; +} + function storedStageTimings(storedTimings: Record | null): StageTiming[] { if (storedTimings === null) return []; return arrayRecords(storedTimings.stages) @@ -151,6 +165,8 @@ function storedStageTimings(storedTimings: Record | null): Stag numberOrNull(stage.budgetSeconds), stringOrNull(stage.source) ?? "stored-state", stringOrNull(stage.object), + stringOrNull(stage.startedAt), + stringOrNull(stage.finishedAt), )) .filter((stage) => stage.stage.length > 0) .slice(0, 24); @@ -222,7 +238,7 @@ function stageTimingsFromNativePayload(payload: Record | null, if (payload === null) return []; const stages: StageTiming[] = []; const statusRead = asOptionalRecord(asOptionalRecord(payload.timings)?.statusRead); - stages.push(stageTiming("status-read", "ok", secondsFromMs(numberOrNull(statusRead?.elapsedMs)), numberOrNull(statusRead?.budgetSeconds), "native-status", null)); + stages.push(stageTiming("status-read", "ok", secondsFromMs(numberOrNull(statusRead?.elapsedMs)), numberOrNull(statusRead?.budgetSeconds), "native-status", null, stringOrNull(statusRead?.startedAt), stringOrNull(statusRead?.finishedAt))); const sourceSyncStage = k8sJobTiming("git-mirror-sync", asOptionalRecord(payload.sourceSync)); if (sourceSyncStage !== null) stages.push(sourceSyncStage); const reuseConfig = asOptionalRecord(payload.reuseConfig); @@ -237,18 +253,18 @@ function stageTimingsFromNativePayload(payload: Record | null, const tekton = asOptionalRecord(payload.tekton); if (tekton !== null) { const status = tekton.succeeded === true ? "succeeded" : tekton.succeeded === false ? `failed:${stringOrNull(tekton.reason) ?? "unknown"}` : "running"; - stages.push(stageTiming("pipelinerun", status, numberOrNull(tekton.durationSeconds), null, "tekton", stringOrNull(tekton.name))); + stages.push(stageTiming("pipelinerun", status, numberOrNull(tekton.durationSeconds), null, "tekton", stringOrNull(tekton.name), stringOrNull(tekton.startTime), stringOrNull(tekton.completionTime))); } const taskRuns = asOptionalRecord(payload.taskRuns); for (const record of taskRuns === null ? [] : prioritizedTaskRunItems(taskRuns)) { const name = stringOrNull(record.pipelineTask) ?? stringOrNull(record.name) ?? "unknown"; const status = record.status === "True" ? "succeeded" : record.status === "False" ? `failed:${stringOrNull(record.reason) ?? "unknown"}` : "running"; - stages.push(stageTiming(`task:${name}`, status, numberOrNull(record.durationSeconds), null, "tekton-taskrun", stringOrNull(record.name))); + stages.push(stageTiming(`task:${name}`, status, numberOrNull(record.durationSeconds), null, "tekton-taskrun", stringOrNull(record.name), stringOrNull(record.startTime), stringOrNull(record.completionTime))); } const argo = asOptionalRecord(payload.argo); if (argo !== null) { const sameWindow = total === null || timingOverlapsTotal(total, stringOrNull(argo.operationStartedAt), stringOrNull(argo.operationFinishedAt)); - stages.push(stageTiming("argo", `${sameWindow ? "" : "current:"}${stringOrNull(argo.syncStatus) ?? "unknown"}/${stringOrNull(argo.healthStatus) ?? "unknown"}`, sameWindow ? numberOrNull(argo.operationDurationSeconds) : null, null, sameWindow ? "argocd" : "argocd-current", stringOrNull(argo.name))); + stages.push(stageTiming("argo", `${sameWindow ? "" : "current:"}${stringOrNull(argo.syncStatus) ?? "unknown"}/${stringOrNull(argo.healthStatus) ?? "unknown"}`, sameWindow ? numberOrNull(argo.operationDurationSeconds) : null, null, sameWindow ? "argocd" : "argocd-current", stringOrNull(argo.name), stringOrNull(argo.operationStartedAt), stringOrNull(argo.operationFinishedAt))); } const runtime = asOptionalRecord(payload.runtime); if (runtime !== null) { @@ -296,7 +312,7 @@ function stageTimingsFromCommand(command: Record | undefined): const tektonSeconds = secondsFromMs(numberOrNull(payload.elapsedMs)); if (tektonSeconds !== null) { const status = payload.completed === true ? "completed" : payload.failed === true ? "failed" : payload.stillRunning === true ? "running" : "submitted"; - stages.push(stageTiming("pipelinerun-wait", status, tektonSeconds, null, "tekton-submit", stringOrNull(command.pipelineRun))); + stages.push(stageTiming("pipelinerun-wait", status, tektonSeconds, null, "tekton-submit", stringOrNull(command.pipelineRun), stringOrNull(payload.startedAt), stringOrNull(payload.finishedAt))); } } const closeout = asOptionalRecord(command.closeout); @@ -305,7 +321,7 @@ function stageTimingsFromCommand(command: Record | undefined): const gitMirrorFlushStage = k8sJobTiming("git-mirror-flush", asOptionalRecord(gitMirrorFlush?.result), stringOrNull(gitMirrorFlush?.jobName)); if (gitMirrorFlushStage !== null) stages.push(gitMirrorFlushStage); const status = closeout.completed === true ? "completed" : closeout.timedOut === true ? "over-budget" : "pending"; - stages.push(stageTiming("closeout", status, secondsFromMs(numberOrNull(closeout.elapsedMs)), null, "k8s-native-closeout", stringOrNull(command.pipelineRun))); + stages.push(stageTiming("closeout", status, secondsFromMs(numberOrNull(closeout.elapsedMs)), null, "k8s-native-closeout", stringOrNull(command.pipelineRun), stringOrNull(closeout.startedAt), stringOrNull(closeout.finishedAt))); } return stages; } @@ -313,11 +329,11 @@ function stageTimingsFromCommand(command: Record | undefined): function k8sJobTiming(stage: string, job: Record | null, objectOverride?: string | null): StageTiming | null { if (job === null) return null; const status = job.completed === true ? job.reused === true ? "reused" : "completed" : job.failed === true ? "failed" : job.timedOut === true ? "over-budget" : "running"; - return stageTiming(stage, status, secondsFromMs(numberOrNull(job.elapsedMs)), null, "kubernetes-job", objectOverride ?? stringOrNull(job.jobName)); + return stageTiming(stage, status, secondsFromMs(numberOrNull(job.elapsedMs)), null, "kubernetes-job", objectOverride ?? stringOrNull(job.jobName), stringOrNull(job.startedAt), stringOrNull(job.finishedAt)); } -function stageTiming(stage: string, status: string, seconds: number | null, budgetSeconds: number | null, source: string, object: string | null): StageTiming { - return { stage, status, seconds, budgetSeconds, source, object }; +function stageTiming(stage: string, status: string, seconds: number | null, budgetSeconds: number | null, source: string, object: string | null, startedAt?: string | null, finishedAt?: string | null): StageTiming { + return { stage, status, seconds, budgetSeconds, source, object, startedAt: startedAt ?? null, finishedAt: finishedAt ?? null }; } function dedupeTimingStages(stages: StageTiming[]): StageTiming[] { diff --git a/scripts/src/cicd-types.ts b/scripts/src/cicd-types.ts index ed548b87..95a40a03 100644 --- a/scripts/src/cicd-types.ts +++ b/scripts/src/cicd-types.ts @@ -269,6 +269,8 @@ export interface NativeK8sJobResult { namespace: string; polls: number; elapsedMs: number; + startedAt: string | null; + finishedAt: string | null; logsTail: string | null; summary: Record | null; conditionReason: string | null; @@ -284,6 +286,8 @@ export interface StageTiming { budgetSeconds: number | null; source: string; object: string | null; + startedAt?: string | null; + finishedAt?: string | null; } export interface FollowerState {