From 5a6490505431f00629b96a55f97256cfa3c55ab9 Mon Sep 17 00:00:00 2001 From: Lyon <88232613+pikasTech@users.noreply.github.com> Date: Tue, 23 Jun 2026 18:26:44 +0800 Subject: [PATCH] fix(web-probe): report trace order and card timing mismatches (#746) Co-authored-by: Codex --- .../hwlab-node-web-observe-runner-source.ts | 167 ++++++++++++++++-- 1 file changed, 155 insertions(+), 12 deletions(-) diff --git a/scripts/src/hwlab-node-web-observe-runner-source.ts b/scripts/src/hwlab-node-web-observe-runner-source.ts index 6bf9d2f6..1e851d9b 100644 --- a/scripts/src/hwlab-node-web-observe-runner-source.ts +++ b/scripts/src/hwlab-node-web-observe-runner-source.ts @@ -1577,9 +1577,25 @@ async function sampleOnePage(targetPage, { reason, groupSeq, pageRole, targetPag } return trim(clone.textContent || "", 1200); }; + const numericAttr = (element, names) => { + for (const name of names) { + const raw = element.getAttribute(name); + const value = Number(raw); + if (Number.isFinite(value)) return value; + } + return null; + }; + const textAttr = (element, names) => { + for (const name of names) { + const raw = element.getAttribute(name); + if (raw && String(raw).trim()) return String(raw).trim(); + } + return null; + }; const summarize = (selector, limit) => Array.from(document.querySelectorAll(selector)).filter(visible).slice(-limit).map((element, index) => { const rect = element.getBoundingClientRect(); const owner = element.closest('article.message-card, .message-card[data-message-id], article[data-message-id], [data-trace-id]'); + const timeElement = element.matches("time,[datetime]") ? element : element.querySelector("time,[datetime]"); return { index, tag: element.tagName.toLowerCase(), @@ -1590,6 +1606,12 @@ async function sampleOnePage(targetPage, { reason, groupSeq, pageRole, targetPag messageId: element.getAttribute("data-message-id") || owner?.getAttribute("data-message-id") || element.getAttribute("id") || null, traceId: element.getAttribute("data-trace-id") || owner?.getAttribute("data-trace-id") || null, turnId: element.getAttribute("data-turn-id") || owner?.getAttribute("data-turn-id") || null, + projectedSeq: numericAttr(element, ["data-projected-seq", "data-projectedseq", "data-seq", "data-sequence", "aria-posinset"]), + sourceSeq: numericAttr(element, ["data-source-seq", "data-sourceseq", "data-source-event-seq"]), + eventSeq: numericAttr(element, ["data-event-seq", "data-eventseq"]), + eventTimestamp: textAttr(element, ["data-event-ts", "data-event-time", "data-timestamp", "datetime"]) || (timeElement ? textAttr(timeElement, ["datetime", "data-event-ts", "data-event-time", "data-timestamp"]) : null), + eventTimeText: timeElement ? trim(timeElement.textContent || "", 80) : null, + eventKind: textAttr(element, ["data-event-kind", "data-kind", "data-label", "data-status"]) || element.getAttribute("aria-label") || null, text: textHashInput(element), rect: { x: Math.round(rect.x), y: Math.round(rect.y), width: Math.round(rect.width), height: Math.round(rect.height) }, }; @@ -2266,6 +2288,63 @@ console.log(JSON.stringify({ pagePerformancePartialApi: recentWindow.pagePerformance.sameOriginApiByPath.filter((item) => item.isLongLivedStream !== true && Number(item.partialOverBudgetCount ?? item.partialOverFiveSecondCount ?? 0) > 0).slice(0, 5).map((item) => ({ path: item.path, route: item.route, sampleCount: item.sampleCount, completeTimingSampleCount: item.completeTimingSampleCount, partialTimingSampleCount: item.partialTimingSampleCount, partialOverBudgetCount: item.partialOverBudgetCount, budgetMs: item.partialBudgetMs, partialOverFiveSecondCount: item.partialOverFiveSecondCount, partialSamples: item.partialSamples })), pagePerformanceSseStreams: recentWindow.pagePerformance.sameOriginApiByPath.filter((item) => item.isLongLivedStream === true).slice(0, 5).map((item) => ({ path: item.path, route: item.route, sampleCount: item.sampleCount, streamOpenSampleCount: item.streamOpenSampleCount, streamOpenP95Ms: item.streamOpenP95Ms, streamOpenMaxMs: item.streamOpenMaxMs, streamOpenOverBudgetCount: item.streamOpenOverBudgetCount, streamOpenBudgetMs: item.streamOpenBudgetMs, streamOpenOverFiveSecondCount: item.streamOpenOverFiveSecondCount, streamLifetimeOverFiveSecondCount: item.streamLifetimeOverFiveSecondCount, slowSamples: item.slowSamples })), findings: prioritizeFindings(recentWindow.findings).slice(0, 8).map((item) => ({ kind: item.id ?? item.kind ?? item.code, severity: item.severity, count: item.count ?? item.sampleCount ?? null, summary: String(item.summary ?? item.message ?? "").slice(0, 180) })), + traceOrderAnomalies: (recentWindow.sampleMetrics?.traceOrder?.orderAnomalies || []).slice(0, 8).map((item) => ({ + sampleSeq: item.sampleSeq ?? null, + sampleIndex: item.sampleIndex ?? null, + timestamp: item.timestamp ?? null, + pageRole: item.pageRole ?? null, + traceId: item.traceId ?? null, + reasons: item.reasons ?? [], + previousRowIndex: item.previousRowIndex ?? null, + currentRowIndex: item.currentRowIndex ?? null, + previousTotalSeconds: item.previousTotalSeconds ?? null, + currentTotalSeconds: item.currentTotalSeconds ?? null, + previousProjectedSeq: item.previousProjectedSeq ?? null, + currentProjectedSeq: item.currentProjectedSeq ?? null, + previousSourceSeq: item.previousSourceSeq ?? null, + currentSourceSeq: item.currentSourceSeq ?? null, + previousEventSeq: item.previousEventSeq ?? null, + currentEventSeq: item.currentEventSeq ?? null, + previousPreview: String(item.previousPreview || "").slice(0, 120), + currentPreview: String(item.currentPreview || "").slice(0, 120), + })), + traceCompletionNotLast: (recentWindow.sampleMetrics?.traceOrder?.completionNotLast || []).slice(0, 8).map((item) => ({ + sampleSeq: item.sampleSeq ?? null, + sampleIndex: item.sampleIndex ?? null, + timestamp: item.timestamp ?? null, + pageRole: item.pageRole ?? null, + traceId: item.traceId ?? null, + completionRowIndex: item.completionRowIndex ?? null, + laterRowIndex: item.laterRowIndex ?? null, + completionTotalSeconds: item.completionTotalSeconds ?? null, + laterTotalSeconds: item.laterTotalSeconds ?? null, + completionProjectedSeq: item.completionProjectedSeq ?? null, + laterProjectedSeq: item.laterProjectedSeq ?? null, + completionPreview: String(item.completionPreview || "").slice(0, 120), + laterPreview: String(item.laterPreview || "").slice(0, 120), + })), + roundCompletionElapsedMismatches: (recentWindow.sampleMetrics?.codeAgentCardTiming?.roundCompletion?.elapsedMismatches || []).slice(0, 8).map((item) => ({ + seq: item.seq ?? null, + ts: item.ts ?? null, + pageRole: item.pageRole ?? null, + promptIndex: item.promptIndex ?? null, + traceId: item.traceId ?? null, + completionElapsedSeconds: item.completionElapsedSeconds ?? null, + cardTotalElapsedSeconds: item.cardTotalElapsedSeconds ?? null, + deltaSeconds: item.deltaSeconds ?? null, + toleranceSeconds: item.toleranceSeconds ?? null, + })), + codeAgentCardDurationUnderreported: (recentWindow.sampleMetrics?.codeAgentCardTiming?.durationUnderreported || []).slice(0, 8).map((item) => ({ + sampleIndex: item.sampleIndex ?? null, + timestamp: item.timestamp ?? null, + pageRole: item.pageRole ?? null, + traceId: item.traceId ?? null, + cardTotalElapsedSeconds: item.cardTotalElapsedSeconds ?? null, + expectedElapsedSeconds: item.expectedElapsedSeconds ?? null, + deltaSeconds: item.deltaSeconds ?? null, + evidenceKind: item.evidenceKind ?? null, + evidencePreview: String(item.evidencePreview || "").slice(0, 120), + })), valuesRedacted: true, })); @@ -2482,6 +2561,12 @@ function compactDomItem(item) { messageId: item.messageId ?? null, traceId: item.traceId ?? null, turnId: item.turnId ?? null, + projectedSeq: Number.isFinite(Number(item.projectedSeq)) ? Number(item.projectedSeq) : null, + sourceSeq: Number.isFinite(Number(item.sourceSeq)) ? Number(item.sourceSeq) : null, + eventSeq: Number.isFinite(Number(item.eventSeq)) ? Number(item.eventSeq) : null, + eventTimestamp: item.eventTimestamp ?? null, + eventTimeText: item.eventTimeText ?? null, + eventKind: item.eventKind ?? null, durationText: item.durationText ?? null, activityText: item.activityText ?? null, className: item.className ?? null, @@ -4526,7 +4611,8 @@ function buildTraceOrderMetrics(samples, timeline) { const normalized = { ...row, sampleIndex, - timestamp: sample.timestamp || sample.collectedAt || sample.time || null, + sampleSeq: sample.seq ?? null, + timestamp: sample.ts || sample.timestamp || sample.collectedAt || sample.time || null, pageRole: row.pageRole || sample.pageRole || sample.role || sample.contextRole || null, pageId: row.pageId || sample.pageId || sample.contextId || null, sessionId: row.sessionId || sample.sessionId || sample.workbenchSessionId || null, @@ -4557,9 +4643,13 @@ function buildTraceOrderMetrics(samples, timeline) { const diff = previous.clockSeconds - row.clockSeconds; if (diff > slackSeconds && diff < 43200) reasons.push('clock-decreased'); } + if (Number.isFinite(previous.timestampMs) && Number.isFinite(row.timestampMs) && row.timestampMs + slackSeconds * 1000 < previous.timestampMs) { + reasons.push('timestamp-decreased'); + } if (reasons.length) { orderAnomalies.push({ sampleIndex: row.sampleIndex, + sampleSeq: row.sampleSeq, timestamp: row.timestamp, pageRole: row.pageRole, pageId: row.pageId, @@ -4572,8 +4662,14 @@ function buildTraceOrderMetrics(samples, timeline) { currentTotalSeconds: row.totalSeconds, previousProjectedSeq: previous.projectedSeq, currentProjectedSeq: row.projectedSeq, + previousSourceSeq: previous.sourceSeq, + currentSourceSeq: row.sourceSeq, + previousEventSeq: previous.eventSeq, + currentEventSeq: row.eventSeq, previousClockSeconds: previous.clockSeconds, currentClockSeconds: row.clockSeconds, + previousTimestampMs: previous.timestampMs, + currentTimestampMs: row.timestampMs, previousPreview: previous.preview, currentPreview: row.preview, }); @@ -4591,6 +4687,7 @@ function buildTraceOrderMetrics(samples, timeline) { if (later) { completionNotLast.push({ sampleIndex: row.sampleIndex, + sampleSeq: row.sampleSeq, timestamp: row.timestamp, pageRole: row.pageRole, pageId: row.pageId, @@ -4600,6 +4697,12 @@ function buildTraceOrderMetrics(samples, timeline) { laterRowIndex: later.rowIndex, completionTotalSeconds: row.totalSeconds, laterTotalSeconds: later.totalSeconds, + completionProjectedSeq: row.projectedSeq, + laterProjectedSeq: later.projectedSeq, + completionSourceSeq: row.sourceSeq, + laterSourceSeq: later.sourceSeq, + completionEventSeq: row.eventSeq, + laterEventSeq: later.eventSeq, completionPreview: row.preview, laterPreview: later.preview, }); @@ -4691,6 +4794,12 @@ function traceTimingRowsForSample(sample, timelineItem) { pageId: item.pageId || item.contextId || candidate.meta?.pageId || null, sessionId: item.sessionId || item.workbenchSessionId || candidate.meta?.sessionId || null, traceId: item.traceId || item.trace_id || candidate.meta?.traceId || null, + projectedSeq: item.projectedSeq ?? item.projected_seq ?? item.projectedSequence ?? null, + sourceSeq: item.sourceSeq ?? item.source_seq ?? item.sourceSequence ?? null, + eventSeq: item.eventSeq ?? item.event_seq ?? item.sequence ?? null, + eventTimestamp: item.eventTimestamp ?? item.event_ts ?? item.timestamp ?? item.ts ?? null, + eventTimeText: item.eventTimeText ?? item.timeText ?? null, + eventKind: item.eventKind ?? item.kind ?? item.status ?? null, }); }); } @@ -4722,6 +4831,10 @@ function extractTraceRowsFromText(text, source, baseIndex, meta = {}) { function normalizeTraceTimingRow(text, source, rowIndex, meta = {}) { const preview = compactOneLine(text).slice(0, 240); + const projectedSeq = firstFiniteNumber(meta.projectedSeq, parseTraceRowProjectedSeq(preview)); + const sourceSeq = firstFiniteNumber(meta.sourceSeq); + const eventSeq = firstFiniteNumber(meta.eventSeq); + const timestampMs = parseTraceRowTimestampMs(meta.eventTimestamp || meta.eventTimeText || preview); return { source, rowIndex, @@ -4730,10 +4843,16 @@ function normalizeTraceTimingRow(text, source, rowIndex, meta = {}) { pageId: meta.pageId || null, sessionId: meta.sessionId || null, traceId: meta.traceId || parseTraceRowTraceId(preview), - clockSeconds: parseTraceRowClockSeconds(preview), + clockSeconds: parseTraceRowClockSeconds(preview) ?? parseTraceRowClockSeconds(meta.eventTimeText || ""), + timestampMs, totalSeconds: parseTraceRowTotalSeconds(preview), - projectedSeq: parseTraceRowProjectedSeq(preview), - isCompletion: /轮次完成|turn\s+completed|completed\s+turn/i.test(preview), + projectedSeq, + sourceSeq, + eventSeq, + eventTimestamp: meta.eventTimestamp || null, + eventTimeText: meta.eventTimeText || null, + eventKind: meta.eventKind || null, + isCompletion: /轮次完成|turn\s+completed|completed\s+turn|terminal[_: -]?status|backend[_: -]?turn[_: -]?finished/i.test([preview, meta.eventKind || ""].join(" ")), }; } @@ -4829,6 +4948,21 @@ function parseTraceRowProjectedSeq(text) { return match ? Number(match[1]) : null; } +function parseTraceRowTimestampMs(value) { + const text = String(value || '').trim(); + if (!text) return null; + const parsed = Date.parse(text); + return Number.isFinite(parsed) ? parsed : null; +} + +function firstFiniteNumber(...values) { + for (const value of values) { + const numeric = Number(value); + if (Number.isFinite(numeric)) return numeric; + } + return null; +} + function parseTraceRowTraceId(text) { const match = String(text || '').match(/\b(?:trace_id=|traceId[:=]?\s*)(trc_[a-z0-9_-]+|[a-f0-9]{16,})\b/i); return match ? match[1] : null; @@ -5083,10 +5217,13 @@ function buildRoundCompletionMetrics(samples, timeline, turnTiming) { function roundCompletionEventsForSample(sample, timelineItem) { const rows = []; - for (const item of Array.isArray(sample?.traceRows) ? sample.traceRows : []) { - const text = String(item?.text || item?.textPreview || ""); - if (!/轮次完成/iu.test(text)) continue; - const elapsedValues = parseTotalElapsedSeconds(text).filter(Number.isFinite); + for (const item of traceTimingRowsForSample(sample, timelineItem)) { + const text = String(item?.preview || item?.text || item?.textPreview || ""); + if (!item?.isCompletion && !/轮次完成/iu.test(text)) continue; + const elapsedValues = [ + Number(item?.totalSeconds), + ...parseTotalElapsedSeconds(text).filter(Number.isFinite) + ].filter(Number.isFinite); const attributed = inferRoundCompletionCard(sample, text); rows.push({ ...ref(sample), @@ -5094,7 +5231,7 @@ function roundCompletionEventsForSample(sample, timelineItem) { traceId: item?.traceId ?? firstTraceId([text]) ?? attributed?.traceId ?? null, messageId: item?.messageId ?? attributed?.messageId ?? null, attributed: Boolean(item?.traceId || item?.messageId || attributed?.traceId || attributed?.messageId), - traceRowIndex: item?.index ?? null, + traceRowIndex: item?.rowIndex ?? item?.index ?? null, elapsedSeconds: elapsedValues.length > 0 ? Math.max(...elapsedValues) : null, textHash: item?.textHash ?? sha256(text), preview: limitText(text, 180), @@ -5120,9 +5257,15 @@ function inferRoundCompletionCard(sample, text) { } function cardMetricItemsForCompletion(sample, timelineItem, event) { - if (!event.traceId && !event.messageId) return []; - return turnMetricItems(sample, timelineItem) + const metrics = turnMetricItems(sample, timelineItem) .filter((item) => item.promptIndex === event.promptIndex) + .filter((item) => item.pageRole === event.pageRole || !event.pageRole) + .filter((item) => item.pageId === event.pageId || !event.pageId); + if (!event.traceId && !event.messageId) { + const withElapsed = metrics.filter((item) => Number.isFinite(Number(item.totalElapsedSeconds))); + return withElapsed.length === 1 ? withElapsed : []; + } + return metrics .filter((item) => !event.traceId || !item.traceId || item.traceId === event.traceId) .filter((item) => !event.messageId || !item.messageId || item.messageId === event.messageId) .sort((left, right) => { @@ -5135,7 +5278,7 @@ function cardMetricItemsForCompletion(sample, timelineItem, event) { } function hasFinalResponseAfterCompletion(samples, timeline, event) { - if (!event.traceId && !event.messageId) return true; + if (!event.traceId && !event.messageId && !event.promptIndex) return true; const eventTsMs = Date.parse(String(event.ts || "")); for (let index = 0; index < (Array.isArray(samples) ? samples : []).length; index += 1) { const sample = samples[index];