From 5d69083da789a5bf9348eeb9400a7cbc14770abe Mon Sep 17 00:00:00 2001 From: tianxiaochannel-oss88 Date: Mon, 2 Nov 2026 03:11:41 +0800 Subject: [PATCH 1/3] ci: add non-blocking timing telemetry --- .github/workflows/ci.yml | 66 +++++++++ docs/maintenance/ci.md | 9 ++ scripts/ci/README.md | 17 +++ scripts/ci/ci-telemetry.mjs | 214 +++++++++++++++++++++++++++ scripts/ci/ci-telemetry.test.mjs | 79 ++++++++++ scripts/ci/runtime-workflow.test.mjs | 14 ++ 6 files changed, 399 insertions(+) create mode 100644 scripts/ci/ci-telemetry.mjs create mode 100644 scripts/ci/ci-telemetry.test.mjs diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 22dc140d4..90738809f 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -671,6 +671,9 @@ jobs: if: always() runs-on: ubuntu-latest timeout-minutes: 5 + permissions: + actions: read + contents: read steps: - name: Check out quality policy without retained credentials uses: actions/checkout@3d3c42e5aac5ba805825da76410c181273ba90b1 @@ -732,3 +735,66 @@ jobs: with: path: .codex-artifacts/ci/timings.json key: ci-node-timings-v1-${{ github.run_id }}-${{ github.run_attempt }} + + - name: Collect workflow timing metadata + if: always() + shell: bash + env: + GH_TOKEN: ${{ github.token }} + run: | + set -u + mkdir -p .codex-artifacts/ci + run_status=0 + gh api "repos/${GITHUB_REPOSITORY}/actions/runs/${GITHUB_RUN_ID}" > .codex-artifacts/ci/telemetry-run.json || run_status=$? + if [ "$run_status" -ne 0 ]; then + printf '{"telemetry_unavailable":true,"reason":"workflow run API request failed"}\n' > .codex-artifacts/ci/telemetry-run.json + fi + jobs_status=0 + gh api --paginate --slurp "repos/${GITHUB_REPOSITORY}/actions/runs/${GITHUB_RUN_ID}/jobs?per_page=100" > .codex-artifacts/ci/telemetry-jobs-pages.json || jobs_status=$? + if [ "$jobs_status" -ne 0 ]; then + printf '{"telemetry_unavailable":true,"reason":"workflow jobs API request failed"}\n' > .codex-artifacts/ci/telemetry-jobs-pages.json + else + node --input-type=module <<'NODE' + import { readFile, writeFile } from "node:fs/promises"; + const pages = JSON.parse(await readFile(".codex-artifacts/ci/telemetry-jobs-pages.json", "utf8")); + const jobs = Array.isArray(pages) ? pages.flatMap(page => page?.jobs ?? []) : []; + await writeFile(".codex-artifacts/ci/telemetry-jobs.json", `${JSON.stringify({ jobs }, null, 2)}\n`); + NODE + fi + if [ ! -f .codex-artifacts/ci/telemetry-jobs.json ]; then + printf '{"jobs":[],"telemetry_unavailable":true}\n' > .codex-artifacts/ci/telemetry-jobs.json + fi + + - name: Render CI timing telemetry + if: always() + shell: bash + run: | + set +e + node scripts/ci/ci-telemetry.mjs \ + --run=.codex-artifacts/ci/telemetry-run.json \ + --jobs=.codex-artifacts/ci/telemetry-jobs.json \ + --reports-dir=.codex-artifacts/ci/reports \ + --output=.codex-artifacts/ci/ci-telemetry.json \ + --summary=.codex-artifacts/ci/ci-telemetry.md + telemetry_status=$? + if [ "$telemetry_status" -ne 0 ]; then + printf '{"version":1,"telemetryUnavailable":true}\n' > .codex-artifacts/ci/ci-telemetry.json + printf '## CI timing telemetry\n\nTelemetry was unavailable; this did not affect the quality gate.\n' > .codex-artifacts/ci/ci-telemetry.md + echo "Warning: CI timing telemetry was unavailable" >&2 + fi + cat .codex-artifacts/ci/ci-telemetry.md >> "$GITHUB_STEP_SUMMARY" + exit 0 + + - name: Preserve CI timing telemetry + if: always() + uses: actions/upload-artifact@cf430e030ddbb5b0abf93d22962f4752f3646cd9 + with: + name: ci-telemetry + include-hidden-files: true + if-no-files-found: warn + retention-days: 14 + path: | + .codex-artifacts/ci/ci-telemetry.json + .codex-artifacts/ci/ci-telemetry.md + .codex-artifacts/ci/telemetry-run.json + .codex-artifacts/ci/telemetry-jobs.json diff --git a/docs/maintenance/ci.md b/docs/maintenance/ci.md index 7a87decb8..a58c52883 100644 --- a/docs/maintenance/ci.md +++ b/docs/maintenance/ci.md @@ -129,6 +129,15 @@ Linux 每日回归仅在同一提交、同一检查方案已有有效的完整 每次运行分别记录排队时间、页面总时长、各任务运行时间、Linux／macOS 累计任务分钟、测试数量与原生跳过数量。累计任务分钟是性能观察，不能在没有账单证据时称为实际扣额；失败任务已运行的部分也会消耗资源。 +当前 `quality` 汇总任务还会保存非阻断的 `ci-telemetry` artifact（保留 14 +天），记录 workflow run、job、step、shard 和测试文件耗时，以及 +`critical_path_duration`、Core/Daemon 最大 shard 耗时、分片不均衡比和 +timeout/leaked-process 计数。摘要会写入 GitHub Step Summary；Actions API +不可用、报告缺失或 telemetry 解析失败时只标记观测不可用，不改变原有质量门。 +由于采集步骤位于汇总任务内部，run 总时长标为采集时已观测值。先观察至少 +5～10 次完整 hosted run，再决定是否调整分片、worker 并发或增加 E2E；当前 +不据此承诺固定提速比例。 + 缓存继续用于锁定依赖和同一次构建输出复用。不得复用与提交、平台或方案不匹配的测试成功。分片缩短等待不一定减少累计费用；不在测量前承诺节省比例，也不把公开仓库、自托管 runner 或增加支出上限当作本轮方案的前提。 ## 实施顺序与验收 diff --git a/scripts/ci/README.md b/scripts/ci/README.md index b3c14353f..887103498 100644 --- a/scripts/ci/README.md +++ b/scripts/ci/README.md @@ -43,6 +43,23 @@ cancellations, launch errors and log/cleanup failures fail the job. The aggregat requires every planned file to have passed exactly once before saving new timing hints. Only successful default-branch runs publish timing caches. +## Timing Telemetry + +The `quality` job also preserves a non-blocking `ci-telemetry` artifact for +complete and preview runs. It records workflow run and job timestamps, +estimated queue and execution time, step durations, shard/file durations, +`critical_path_duration`, `max_core_shard_duration`, +`max_daemon_shard_duration`, shard imbalance by suite, and timeout/leaked-process +counters. The summary is appended to the GitHub step summary and the raw JSON +is retained for 14 days. Collection uses the current run's Actions API data; +API or parsing failures create an unavailable observation and never change the +quality gate. Run duration is labelled as observed at collection because the +telemetry step runs inside the aggregate job. + +Use at least 5-10 complete hosted runs to compare the observations before +changing shard counts, worker concurrency, or adding another E2E lane. The +telemetry does not establish a fixed speedup percentage by itself. + Generate a local plan without running tests: ```sh diff --git a/scripts/ci/ci-telemetry.mjs b/scripts/ci/ci-telemetry.mjs new file mode 100644 index 000000000..6ddd521da --- /dev/null +++ b/scripts/ci/ci-telemetry.mjs @@ -0,0 +1,214 @@ +import { readFile, writeFile, mkdir, readdir } from "node:fs/promises"; +import { dirname, join, resolve } from "node:path"; +import { pathToFileURL } from "node:url"; + +const MAX_REASONABLE_MS = 7 * 24 * 60 * 60 * 1000; + +function parseTimestamp(value) { + const timestamp = Date.parse(value ?? ""); + return Number.isFinite(timestamp) ? timestamp : null; +} + +function duration(start, end) { + const started = parseTimestamp(start); + const completed = parseTimestamp(end); + if (started === null || completed === null || completed < started || completed - started > MAX_REASONABLE_MS) return null; + return completed - started; +} + +function sum(values) { + return values.reduce((total, value) => total + (Number.isFinite(value) && value >= 0 ? value : 0), 0); +} + +function percentile(values, fraction) { + const sorted = values.filter(Number.isFinite).sort((a, b) => a - b); + if (!sorted.length) return null; + return sorted[Math.min(sorted.length - 1, Math.floor((sorted.length - 1) * fraction))]; +} + +function normalizeJobs(input) { + if (Array.isArray(input)) return input; + if (Array.isArray(input?.jobs)) return input.jobs; + return []; +} + +function normalizeReports(input) { + if (!Array.isArray(input)) return []; + return input.filter(report => report && report.version === 1 && typeof report.suite === "string" + && Number.isInteger(report.shard) && Array.isArray(report.results)); +} + +function parseArguments(argv, allowed) { + const args = {}; + for (let index = 0; index < argv.length; index += 1) { + const [key, ...valueParts] = argv[index].split("="); + if (!allowed.includes(key) || Object.hasOwn(args, key)) throw new Error(`Unknown or duplicate argument: ${key}`); + const value = valueParts.length ? valueParts.join("=") : argv[++index]; + if (!value || value.startsWith("--")) throw new Error(`Missing value for ${key}`); + args[key] = value; + } + return args; +} + +async function readReportsDirectory(directory) { + try { + const files = (await readdir(directory)).filter(file => file.endsWith(".json")).sort(); + const reports = []; + for (const file of files) { + try { + reports.push(JSON.parse(await readFile(join(directory, file), "utf8"))); + } catch { + // A failed shard must not turn observation into a quality failure. + } + } + return reports; + } catch { + return []; + } +} + +function jobTelemetry(jobs, run) { + const runCreated = parseTimestamp(run.created_at); + const runStarted = parseTimestamp(run.run_started_at) ?? runCreated; + return jobs.map(job => { + const executionMs = duration(job.started_at, job.completed_at); + const queuedMs = runStarted !== null && parseTimestamp(job.started_at) !== null + ? Math.max(0, parseTimestamp(job.started_at) - runStarted) : null; + const stepDurations = (job.steps ?? []).map(step => ({ + name: step.name, + conclusion: step.conclusion ?? null, + durationMs: duration(step.started_at, step.completed_at), + })); + return { + name: job.name ?? "unnamed", + status: job.status ?? null, + conclusion: job.conclusion ?? null, + runner: job.runner_name ?? null, + queuedMs, + executionMs, + stepDurations, + }; + }); +} + +function reportTelemetry(reports) { + const shards = reports.map(report => { + const durations = report.results.map(result => result.durationMs).filter(value => Number.isFinite(value) && value >= 0); + const statuses = Object.fromEntries([...new Set(report.results.map(result => result.status))] + .map(status => [status, report.results.filter(result => result.status === status).length])); + return { + suite: report.suite, + shard: report.shard, + platform: report.platform ?? null, + complete: report.complete === true, + fileCount: report.results.length, + passedCount: report.results.filter(result => result.status === "passed").length, + statusCounts: statuses, + sumFileDurationMs: sum(durations), + maxFileDurationMs: durations.length ? Math.max(...durations) : null, + p95FileDurationMs: percentile(durations, 0.95), + }; + }); + const bySuite = {}; + for (const shard of shards) (bySuite[shard.suite] ??= []).push(shard); + const suites = Object.fromEntries(Object.entries(bySuite).map(([suite, entries]) => { + const durations = entries.map(entry => entry.sumFileDurationMs).filter(value => value > 0); + const max = durations.length ? Math.max(...durations) : null; + const average = durations.length ? sum(durations) / durations.length : null; + return [suite, { + shardCount: entries.length, + maxShardFileDurationMs: max, + averageShardFileDurationMs: average, + imbalanceRatio: max !== null && average ? max / average : null, + }]; + })); + return { shards, suites }; +} + +export function buildTelemetry({ run = {}, jobs = [], reports = [] } = {}) { + const normalizedJobs = normalizeJobs(jobs); + const normalizedReports = normalizeReports(reports); + const jobDurations = jobTelemetry(normalizedJobs, run); + const runDurationMs = duration(run.created_at, run.updated_at); + const completedAt = normalizedJobs.map(job => parseTimestamp(job.completed_at)).filter(Number.isFinite); + const runCreated = parseTimestamp(run.created_at); + const criticalPathMs = runCreated !== null && completedAt.length && Math.max(...completedAt) >= runCreated + ? Math.min(Math.max(...completedAt) - runCreated, MAX_REASONABLE_MS) : null; + const failedJobs = jobDurations.filter(job => job.conclusion && !["success", "skipped"].includes(job.conclusion)).length; + const timedOutFiles = normalizedReports.flatMap(report => report.results) + .filter(result => result.status === "timed_out").length; + const leakedProcessFiles = normalizedReports.flatMap(report => report.results) + .filter(result => result.status === "leaked_processes").length; + const suiteSummaries = reportTelemetry(normalizedReports).suites; + const finiteJobExecutions = jobDurations.map(job => job.executionMs).filter(Number.isFinite); + const finiteJobQueues = jobDurations.map(job => job.queuedMs).filter(Number.isFinite); + return { + version: 1, + capturedAt: new Date().toISOString(), + telemetryUnavailable: run.telemetry_unavailable === true || jobs.telemetry_unavailable === true, + run: { + id: run.id ?? null, + event: run.event ?? null, + sha: run.head_sha ?? null, + status: run.status ?? null, + conclusion: run.conclusion ?? null, + createdAt: run.created_at ?? null, + startedAt: run.run_started_at ?? null, + updatedAt: run.updated_at ?? null, + durationMs: runDurationMs, + criticalPathMs, + }, + summary: { + jobCount: jobDurations.length, + failedJobCount: failedJobs, + timedOutFileCount: timedOutFiles, + leakedProcessFileCount: leakedProcessFiles, + maxJobExecutionMs: finiteJobExecutions.length ? Math.max(...finiteJobExecutions) : null, + maxJobQueueMs: finiteJobQueues.length ? Math.max(...finiteJobQueues) : null, + maxCoreShardDurationMs: suiteSummaries.core?.maxShardFileDurationMs ?? null, + maxDaemonShardDurationMs: suiteSummaries.daemon?.maxShardFileDurationMs ?? null, + shardImbalanceRatioBySuite: Object.fromEntries(Object.entries(suiteSummaries) + .map(([suite, summary]) => [suite, summary.imbalanceRatio])), + }, + jobs: jobDurations, + reports: reportTelemetry(normalizedReports), + }; +} + +export function renderSummary(telemetry) { + const ms = value => value === null ? "n/a" : `${(value / 60000).toFixed(2)} min`; + const lines = [ + "## CI timing telemetry", + "", + ...(telemetry.telemetryUnavailable ? ["- Collection status: **unavailable**; this did not affect the quality gate."] : []), + `- Run duration observed at collection: **${ms(telemetry.run.durationMs)}**; critical path: **${ms(telemetry.run.criticalPathMs)}**`, + `- Jobs: **${telemetry.summary.jobCount}**; max execution: **${ms(telemetry.summary.maxJobExecutionMs)}**; max queue estimate: **${ms(telemetry.summary.maxJobQueueMs)}**`, + `- Failed jobs: **${telemetry.summary.failedJobCount}**; timed-out files: **${telemetry.summary.timedOutFileCount}**; leaked-process files: **${telemetry.summary.leakedProcessFileCount}**`, + ]; + for (const [suite, data] of Object.entries(telemetry.reports.suites)) { + lines.push(`- ${suite} shards: **${data.shardCount}**; max/average file time: **${ms(data.maxShardFileDurationMs)} / ${ms(data.averageShardFileDurationMs)}**; imbalance: **${data.imbalanceRatio === null ? "n/a" : data.imbalanceRatio.toFixed(2)}x**`); + } + lines.push("", "Per-job and per-file details are retained in the `ci-telemetry` artifact."); + return `${lines.join("\n")}\n`; +} + +async function main() { + const args = parseArguments(process.argv.slice(2), ["--run", "--jobs", "--reports", "--reports-dir", "--output", "--summary"]); + if (!args["--run"] || !args["--jobs"] || !args["--output"] || !args["--summary"] + || (args["--reports"] && args["--reports-dir"])) { + throw new Error("--run, --jobs, --output and --summary are required; use only one reports input"); + } + const run = JSON.parse(await readFile(args["--run"], "utf8")); + const jobs = JSON.parse(await readFile(args["--jobs"], "utf8")); + const reports = args["--reports"] ? JSON.parse(await readFile(args["--reports"], "utf8")) + : args["--reports-dir"] ? await readReportsDirectory(args["--reports-dir"]) : []; + const telemetry = buildTelemetry({ run, jobs, reports }); + await mkdir(dirname(resolve(args["--output"])), { recursive: true }); + await writeFile(args["--output"], `${JSON.stringify(telemetry, null, 2)}\n`); + await writeFile(args["--summary"], renderSummary(telemetry)); + console.log(`Captured CI telemetry for ${telemetry.summary.jobCount} jobs and ${telemetry.reports.shards.length} shard reports.`); +} + +if (process.argv[1] && import.meta.url === pathToFileURL(resolve(process.argv[1])).href) { + try { await main(); } catch (error) { console.error(error); process.exitCode = 1; } +} diff --git a/scripts/ci/ci-telemetry.test.mjs b/scripts/ci/ci-telemetry.test.mjs new file mode 100644 index 000000000..e127ab9f9 --- /dev/null +++ b/scripts/ci/ci-telemetry.test.mjs @@ -0,0 +1,79 @@ +import assert from "node:assert/strict"; +import { mkdir, mkdtemp, readFile, rm, writeFile } from "node:fs/promises"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import { spawn } from "node:child_process"; +import test from "node:test"; +import { buildTelemetry, renderSummary } from "./ci-telemetry.mjs"; + +const run = { + id: 42, + event: "pull_request", + head_sha: "abc123", + created_at: "2026-01-01T00:00:00Z", + run_started_at: "2026-01-01T00:00:10Z", + updated_at: "2026-01-01T00:05:00Z", +}; + +test("builds bounded run, queue, job, and shard telemetry", () => { + const telemetry = buildTelemetry({ + run, + jobs: [{ name: "Daemon tests (shard 0)", status: "completed", conclusion: "success", runner_name: "macos-26", + started_at: "2026-01-01T00:01:00Z", completed_at: "2026-01-01T00:03:00Z", + steps: [{ name: "Run isolated daemon shard", started_at: "2026-01-01T00:02:00Z", completed_at: "2026-01-01T00:02:30Z", conclusion: "success" }] }], + reports: [{ version: 1, suite: "daemon", shard: 0, platform: "darwin", complete: true, results: [ + { file: "test/a.test.mjs", status: "passed", durationMs: 1000 }, + { file: "test/b.test.mjs", status: "timed_out", durationMs: 2000 }, + ] }], + }); + assert.equal(telemetry.run.durationMs, 300000); + assert.equal(telemetry.run.criticalPathMs, 180000); + assert.equal(telemetry.jobs[0].queuedMs, 50000); + assert.equal(telemetry.jobs[0].executionMs, 120000); + assert.equal(telemetry.jobs[0].stepDurations[0].durationMs, 30000); + assert.equal(telemetry.summary.timedOutFileCount, 1); + assert.equal(telemetry.summary.maxDaemonShardDurationMs, 3000); + assert.equal(telemetry.summary.shardImbalanceRatioBySuite.daemon, 1); + assert.equal(telemetry.reports.suites.daemon.imbalanceRatio, 1); + assert.match(renderSummary(telemetry), /timed-out files: \*\*1\*\*/u); +}); + +test("keeps incomplete or malformed timestamps observable without inventing durations", () => { + const telemetry = buildTelemetry({ + run: { created_at: "not-a-date", updated_at: "2026-01-01T00:00:00Z" }, + jobs: [{ name: "broken", started_at: "not-a-date", completed_at: "2026-01-01T00:01:00Z", conclusion: "failure" }], + reports: [{ version: 2, suite: "ignored", shard: 0, results: [] }], + }); + assert.equal(telemetry.run.durationMs, null); + assert.equal(telemetry.jobs[0].executionMs, null); + assert.equal(telemetry.summary.failedJobCount, 1); + assert.equal(telemetry.summary.maxJobExecutionMs, null); + assert.deepEqual(telemetry.reports.shards, []); + assert.equal(buildTelemetry({ run: { telemetry_unavailable: true } }).telemetryUnavailable, true); +}); + +test("CLI reads a report directory and writes both telemetry outputs", async () => { + const directory = await mkdtemp(join(tmpdir(), "ci-telemetry-test-")); + try { + const runPath = join(directory, "run.json"); + const jobsPath = join(directory, "jobs.json"); + const reportsPath = join(directory, "reports"); + const outputPath = join(directory, "nested", "telemetry.json"); + const summaryPath = join(directory, "nested", "telemetry.md"); + await writeFile(runPath, JSON.stringify(run)); + await writeFile(jobsPath, JSON.stringify({ jobs: [] })); + await mkdir(reportsPath); + await writeFile(join(reportsPath, "daemon-0.json"), JSON.stringify({ + version: 1, suite: "daemon", shard: 0, results: [], + })); + const child = spawn(process.execPath, ["scripts/ci/ci-telemetry.mjs", + `--run=${runPath}`, `--jobs=${jobsPath}`, `--reports-dir=${reportsPath}`, + `--output=${outputPath}`, `--summary=${summaryPath}`], { cwd: process.cwd() }); + const [code] = await new Promise(resolve => child.on("close", (status, signal) => resolve([status, signal]))); + assert.equal(code, 0); + assert.equal(JSON.parse(await readFile(outputPath, "utf8")).reports.shards.length, 1); + assert.match(await readFile(summaryPath, "utf8"), /CI timing telemetry/u); + } finally { + await rm(directory, { recursive: true, force: true }); + } +}); diff --git a/scripts/ci/runtime-workflow.test.mjs b/scripts/ci/runtime-workflow.test.mjs index 27615fa63..4ed59d1a2 100644 --- a/scripts/ci/runtime-workflow.test.mjs +++ b/scripts/ci/runtime-workflow.test.mjs @@ -50,6 +50,20 @@ test("the aggregate verifies reports before caching only default-branch successf assert.doesNotMatch(quality, /continue-on-error/u); }); +test("quality preserves non-blocking run, job, and shard timing telemetry", () => { + const quality = job("quality"); + assert.match(quality, /permissions:\n actions: read\n contents: read/u); + assert.match(quality, /GH_TOKEN: \$\{\{ github\.token \}\}/u); + assert.match(quality, /actions\/runs\/\$\{GITHUB_RUN_ID\}/u); + assert.match(quality, /actions\/runs\/\$\{GITHUB_RUN_ID\}\/jobs\?per_page=100/u); + assert.match(quality, /ci-telemetry\.mjs/u); + assert.match(quality, /--reports-dir=\.codex-artifacts\/ci\/reports/u); + assert.match(quality, /cat \.codex-artifacts\/ci\/ci-telemetry\.md >> "\$GITHUB_STEP_SUMMARY"/u); + assert.match(quality, /name: ci-telemetry\n include-hidden-files: true/u); + assert.match(quality, /name: Preserve CI timing telemetry\n if: always\(\)/u); + assert.match(quality, /exit 0/u); +}); + test("complete PR history scans ignore docs-only final diffs while Draft previews stay deferred", () => { const common = job("common-fast"); assert.doesNotMatch(common, /^ if:/mu, "the common job must not bypass history scans based on file scope"); From dfc6a458ed02d93c42e18ea4544f504f1a525e21 Mon Sep 17 00:00:00 2001 From: tianxiaochannel-oss88 Date: Mon, 2 Nov 2026 03:46:30 +0800 Subject: [PATCH 2/3] ci: isolate timing telemetry and correct measurement semantics --- .github/workflows/ci.yml | 44 ++++++- docs/maintenance/ci.md | 15 ++- scripts/ci/README.md | 26 ++-- scripts/ci/ci-telemetry.mjs | 97 ++++++++------- scripts/ci/ci-telemetry.test.mjs | 180 ++++++++++++++++++++++++++- scripts/ci/runtime-workflow.test.mjs | 101 +++++++++++++-- 6 files changed, 382 insertions(+), 81 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 90738809f..40ea8532a 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -671,9 +671,6 @@ jobs: if: always() runs-on: ubuntu-latest timeout-minutes: 5 - permissions: - actions: read - contents: read steps: - name: Check out quality policy without retained credentials uses: actions/checkout@3d3c42e5aac5ba805825da76410c181273ba90b1 @@ -736,13 +733,46 @@ jobs: path: .codex-artifacts/ci/timings.json key: ci-node-timings-v1-${{ github.run_id }}-${{ github.run_attempt }} + timing-telemetry: + name: CI timing telemetry + needs: [scope, quality] + if: always() + runs-on: ubuntu-latest + timeout-minutes: 3 + continue-on-error: true + permissions: + actions: read + contents: read + steps: + - name: Check out timing telemetry without retained credentials + uses: actions/checkout@3d3c42e5aac5ba805825da76410c181273ba90b1 + with: + fetch-depth: 1 + persist-credentials: false + + - name: Set up Node.js + uses: actions/setup-node@949feb2413d6458794dcd2491c4babbbce0c15c1 + with: + node-version: 22.22.1 + + - name: Download available shard reports including failures + if: always() && needs.scope.outputs.execution-tier == 'complete' && (needs.scope.outputs.daemon == 'true' || contains(needs.scope.outputs.test-packages, '"@ling-stack/core"')) + continue-on-error: true + uses: actions/download-artifact@9000827ccba6bdab643e8b6fd33ac0654aef8333 + with: + pattern: ci-test-report-* + merge-multiple: true + path: .codex-artifacts/ci/reports + - name: Collect workflow timing metadata if: always() + continue-on-error: true shell: bash env: GH_TOKEN: ${{ github.token }} run: | set -u + set +e mkdir -p .codex-artifacts/ci run_status=0 gh api "repos/${GITHUB_REPOSITORY}/actions/runs/${GITHUB_RUN_ID}" > .codex-artifacts/ci/telemetry-run.json || run_status=$? @@ -750,23 +780,26 @@ jobs: printf '{"telemetry_unavailable":true,"reason":"workflow run API request failed"}\n' > .codex-artifacts/ci/telemetry-run.json fi jobs_status=0 - gh api --paginate --slurp "repos/${GITHUB_REPOSITORY}/actions/runs/${GITHUB_RUN_ID}/jobs?per_page=100" > .codex-artifacts/ci/telemetry-jobs-pages.json || jobs_status=$? + gh api --paginate --slurp "repos/${GITHUB_REPOSITORY}/actions/runs/${GITHUB_RUN_ID}/attempts/${GITHUB_RUN_ATTEMPT}/jobs?per_page=100" > .codex-artifacts/ci/telemetry-jobs-pages.json || jobs_status=$? if [ "$jobs_status" -ne 0 ]; then printf '{"telemetry_unavailable":true,"reason":"workflow jobs API request failed"}\n' > .codex-artifacts/ci/telemetry-jobs-pages.json else node --input-type=module <<'NODE' import { readFile, writeFile } from "node:fs/promises"; const pages = JSON.parse(await readFile(".codex-artifacts/ci/telemetry-jobs-pages.json", "utf8")); - const jobs = Array.isArray(pages) ? pages.flatMap(page => page?.jobs ?? []) : []; + if (!Array.isArray(pages) || pages.some(page => !Array.isArray(page?.jobs))) throw new Error("Invalid jobs API pages"); + const jobs = pages.flatMap(page => page.jobs); await writeFile(".codex-artifacts/ci/telemetry-jobs.json", `${JSON.stringify({ jobs }, null, 2)}\n`); NODE fi if [ ! -f .codex-artifacts/ci/telemetry-jobs.json ]; then printf '{"jobs":[],"telemetry_unavailable":true}\n' > .codex-artifacts/ci/telemetry-jobs.json fi + exit 0 - name: Render CI timing telemetry if: always() + continue-on-error: true shell: bash run: | set +e @@ -787,6 +820,7 @@ jobs: - name: Preserve CI timing telemetry if: always() + continue-on-error: true uses: actions/upload-artifact@cf430e030ddbb5b0abf93d22962f4752f3646cd9 with: name: ci-telemetry diff --git a/docs/maintenance/ci.md b/docs/maintenance/ci.md index a58c52883..c82cbbd20 100644 --- a/docs/maintenance/ci.md +++ b/docs/maintenance/ci.md @@ -129,12 +129,15 @@ Linux 每日回归仅在同一提交、同一检查方案已有有效的完整 每次运行分别记录排队时间、页面总时长、各任务运行时间、Linux／macOS 累计任务分钟、测试数量与原生跳过数量。累计任务分钟是性能观察，不能在没有账单证据时称为实际扣额；失败任务已运行的部分也会消耗资源。 -当前 `quality` 汇总任务还会保存非阻断的 `ci-telemetry` artifact（保留 14 -天），记录 workflow run、job、step、shard 和测试文件耗时，以及 -`critical_path_duration`、Core/Daemon 最大 shard 耗时、分片不均衡比和 -timeout/leaked-process 计数。摘要会写入 GitHub Step Summary；Actions API -不可用、报告缺失或 telemetry 解析失败时只标记观测不可用，不改变原有质量门。 -由于采集步骤位于汇总任务内部，run 总时长标为采集时已观测值。先观察至少 +独立的 `timing-telemetry` 任务在 `quality` 汇总结束后，尽力保存 +`ci-telemetry` artifact（保留 14 天）并写入 GitHub Step Summary。质量门 +不依赖该任务；采集、下载、解析、上传或观测任务失败都不改变原有门禁。 +质量门失败时仍下载可用分片报告，记录本次运行尝试的 run/job/step 观测、 +逐文件结果、Core/Daemon 最大分片文件累计耗时、分片不均衡比和可用报告中的 +timeout/leaked-process 计数。job 启动延迟包含依赖等待，不能当作纯 runner +排队时间；并发文件累计耗时不等于分片实际时长；截至已完成任务的经过时间 +不等于依赖图关键路径，且不包含仍在执行的任务。run 总时长标为采集时 +已观测值，报告缺失也不能据此断言全量测试没有超时或泄漏。先观察至少 5～10 次完整 hosted run，再决定是否调整分片、worker 并发或增加 E2E；当前 不据此承诺固定提速比例。 diff --git a/scripts/ci/README.md b/scripts/ci/README.md index 887103498..e1a3f4467 100644 --- a/scripts/ci/README.md +++ b/scripts/ci/README.md @@ -45,16 +45,22 @@ hints. Only successful default-branch runs publish timing caches. ## Timing Telemetry -The `quality` job also preserves a non-blocking `ci-telemetry` artifact for -complete and preview runs. It records workflow run and job timestamps, -estimated queue and execution time, step durations, shard/file durations, -`critical_path_duration`, `max_core_shard_duration`, -`max_daemon_shard_duration`, shard imbalance by suite, and timeout/leaked-process -counters. The summary is appended to the GitHub step summary and the raw JSON -is retained for 14 days. Collection uses the current run's Actions API data; -API or parsing failures create an unavailable observation and never change the -quality gate. Run duration is labelled as observed at collection because the -telemetry step runs inside the aggregate job. +The independent `timing-telemetry` job runs after `quality` and preserves a +best-effort `ci-telemetry` artifact for complete and preview runs. The mandatory +quality gate never depends on telemetry, so collection, download, parsing, +upload, or telemetry job failures cannot change that gate. Available shard +reports are downloaded even when the quality gate fails. The artifact retains +run/job/step observations, per-file results, cumulative shard file time, +imbalance by suite, and timeout/leaked-process counts from available reports. +The summary is appended to the GitHub step summary and the JSON is retained +for 14 days. Actions API jobs are restricted to the current run attempt. + +Job start delay includes dependency waits; it is not a pure runner queue +measurement. Cumulative file time is not shard wall-clock time because files +run concurrently. Elapsed time through completed jobs is not a dependency-DAG +critical path and excludes in-progress jobs. Run duration is observed at +collection while the workflow is still in progress. Missing reports do not +establish zero failures across the full run. Use at least 5-10 complete hosted runs to compare the observations before changing shard counts, worker concurrency, or adding another E2E lane. The diff --git a/scripts/ci/ci-telemetry.mjs b/scripts/ci/ci-telemetry.mjs index 6ddd521da..453a540df 100644 --- a/scripts/ci/ci-telemetry.mjs +++ b/scripts/ci/ci-telemetry.mjs @@ -5,7 +5,7 @@ import { pathToFileURL } from "node:url"; const MAX_REASONABLE_MS = 7 * 24 * 60 * 60 * 1000; function parseTimestamp(value) { - const timestamp = Date.parse(value ?? ""); + const timestamp = typeof value === "string" ? Date.parse(value) : NaN; return Number.isFinite(timestamp) ? timestamp : null; } @@ -23,19 +23,18 @@ function sum(values) { function percentile(values, fraction) { const sorted = values.filter(Number.isFinite).sort((a, b) => a - b); if (!sorted.length) return null; - return sorted[Math.min(sorted.length - 1, Math.floor((sorted.length - 1) * fraction))]; + return sorted[Math.max(0, Math.ceil(sorted.length * fraction) - 1)]; } function normalizeJobs(input) { - if (Array.isArray(input)) return input; - if (Array.isArray(input?.jobs)) return input.jobs; - return []; + const jobs = Array.isArray(input) ? input : Array.isArray(input?.jobs) ? input.jobs : []; + return jobs.filter(job => job && typeof job === "object"); } function normalizeReports(input) { if (!Array.isArray(input)) return []; return input.filter(report => report && report.version === 1 && typeof report.suite === "string" - && Number.isInteger(report.shard) && Array.isArray(report.results)); + && report.suite.length > 0 && Number.isInteger(report.shard) && report.shard >= 0 && Array.isArray(report.results)); } function parseArguments(argv, allowed) { @@ -68,13 +67,11 @@ async function readReportsDirectory(directory) { } function jobTelemetry(jobs, run) { - const runCreated = parseTimestamp(run.created_at); - const runStarted = parseTimestamp(run.run_started_at) ?? runCreated; + const runStarted = parseTimestamp(run.run_started_at) !== null ? run.run_started_at : run.created_at; return jobs.map(job => { const executionMs = duration(job.started_at, job.completed_at); - const queuedMs = runStarted !== null && parseTimestamp(job.started_at) !== null - ? Math.max(0, parseTimestamp(job.started_at) - runStarted) : null; - const stepDurations = (job.steps ?? []).map(step => ({ + const startDelayMs = duration(runStarted, job.started_at); + const stepDurations = (Array.isArray(job.steps) ? job.steps : []).filter(step => step && typeof step === "object").map(step => ({ name: step.name, conclusion: step.conclusion ?? null, durationMs: duration(step.started_at, step.completed_at), @@ -84,7 +81,7 @@ function jobTelemetry(jobs, run) { status: job.status ?? null, conclusion: job.conclusion ?? null, runner: job.runner_name ?? null, - queuedMs, + startDelayMs, executionMs, stepDurations, }; @@ -93,26 +90,33 @@ function jobTelemetry(jobs, run) { function reportTelemetry(reports) { const shards = reports.map(report => { - const durations = report.results.map(result => result.durationMs).filter(value => Number.isFinite(value) && value >= 0); - const statuses = Object.fromEntries([...new Set(report.results.map(result => result.status))] - .map(status => [status, report.results.filter(result => result.status === status).length])); + const files = report.results.filter(result => result && typeof result.file === "string").map(result => ({ + file: result.file, + status: typeof result.status === "string" ? result.status : null, + durationMs: Number.isFinite(result.durationMs) && result.durationMs >= 0 && result.durationMs <= MAX_REASONABLE_MS + ? result.durationMs : null, + })); + const durations = files.map(result => result.durationMs).filter(Number.isFinite); + const statuses = Object.fromEntries([...new Set(files.map(result => result.status))] + .map(status => [status, files.filter(result => result.status === status).length])); return { suite: report.suite, shard: report.shard, platform: report.platform ?? null, complete: report.complete === true, - fileCount: report.results.length, - passedCount: report.results.filter(result => result.status === "passed").length, + fileCount: files.length, + passedCount: files.filter(result => result.status === "passed").length, statusCounts: statuses, - sumFileDurationMs: sum(durations), + sumFileDurationMs: durations.length ? sum(durations) : null, maxFileDurationMs: durations.length ? Math.max(...durations) : null, p95FileDurationMs: percentile(durations, 0.95), + files, }; }); - const bySuite = {}; + const bySuite = Object.create(null); for (const shard of shards) (bySuite[shard.suite] ??= []).push(shard); const suites = Object.fromEntries(Object.entries(bySuite).map(([suite, entries]) => { - const durations = entries.map(entry => entry.sumFileDurationMs).filter(value => value > 0); + const durations = entries.map(entry => entry.sumFileDurationMs).filter(Number.isFinite); const max = durations.length ? Math.max(...durations) : null; const average = durations.length ? sum(durations) / durations.length : null; return [suite, { @@ -125,27 +129,31 @@ function reportTelemetry(reports) { return { shards, suites }; } -export function buildTelemetry({ run = {}, jobs = [], reports = [] } = {}) { +export function buildTelemetry({ run = {}, jobs = [], reports = [], capturedAt = new Date().toISOString() } = {}) { + run ??= {}; const normalizedJobs = normalizeJobs(jobs); const normalizedReports = normalizeReports(reports); const jobDurations = jobTelemetry(normalizedJobs, run); - const runDurationMs = duration(run.created_at, run.updated_at); - const completedAt = normalizedJobs.map(job => parseTimestamp(job.completed_at)).filter(Number.isFinite); - const runCreated = parseTimestamp(run.created_at); - const criticalPathMs = runCreated !== null && completedAt.length && Math.max(...completedAt) >= runCreated - ? Math.min(Math.max(...completedAt) - runCreated, MAX_REASONABLE_MS) : null; + const durationSource = run.status === "completed" ? "updated_at" : "capturedAt"; + const runDurationMs = duration(run.created_at, durationSource === "updated_at" ? run.updated_at : capturedAt); + const completedAt = normalizedJobs.filter(job => job.status === "completed") + .map(job => parseTimestamp(job.completed_at)).filter(Number.isFinite); + const completedJobsElapsedMs = completedAt.length + ? duration(run.created_at, new Date(Math.max(...completedAt)).toISOString()) : null; const failedJobs = jobDurations.filter(job => job.conclusion && !["success", "skipped"].includes(job.conclusion)).length; - const timedOutFiles = normalizedReports.flatMap(report => report.results) + const reportDetails = reportTelemetry(normalizedReports); + const files = reportDetails.shards.flatMap(shard => shard.files); + const timedOutFiles = files .filter(result => result.status === "timed_out").length; - const leakedProcessFiles = normalizedReports.flatMap(report => report.results) + const leakedProcessFiles = files .filter(result => result.status === "leaked_processes").length; - const suiteSummaries = reportTelemetry(normalizedReports).suites; + const suiteSummaries = reportDetails.suites; const finiteJobExecutions = jobDurations.map(job => job.executionMs).filter(Number.isFinite); - const finiteJobQueues = jobDurations.map(job => job.queuedMs).filter(Number.isFinite); + const finiteJobStartDelays = jobDurations.map(job => job.startDelayMs).filter(Number.isFinite); return { version: 1, - capturedAt: new Date().toISOString(), - telemetryUnavailable: run.telemetry_unavailable === true || jobs.telemetry_unavailable === true, + capturedAt, + telemetryUnavailable: run.telemetry_unavailable === true || jobs?.telemetry_unavailable === true, run: { id: run.id ?? null, event: run.event ?? null, @@ -156,37 +164,40 @@ export function buildTelemetry({ run = {}, jobs = [], reports = [] } = {}) { startedAt: run.run_started_at ?? null, updatedAt: run.updated_at ?? null, durationMs: runDurationMs, - criticalPathMs, + durationSource, + completedJobsElapsedMs, }, summary: { jobCount: jobDurations.length, failedJobCount: failedJobs, - timedOutFileCount: timedOutFiles, - leakedProcessFileCount: leakedProcessFiles, + availableReportCount: normalizedReports.length, + timedOutFileCount: normalizedReports.length ? timedOutFiles : null, + leakedProcessFileCount: normalizedReports.length ? leakedProcessFiles : null, maxJobExecutionMs: finiteJobExecutions.length ? Math.max(...finiteJobExecutions) : null, - maxJobQueueMs: finiteJobQueues.length ? Math.max(...finiteJobQueues) : null, - maxCoreShardDurationMs: suiteSummaries.core?.maxShardFileDurationMs ?? null, - maxDaemonShardDurationMs: suiteSummaries.daemon?.maxShardFileDurationMs ?? null, + maxJobStartDelayMs: finiteJobStartDelays.length ? Math.max(...finiteJobStartDelays) : null, + maxCoreShardFileDurationMs: suiteSummaries.core?.maxShardFileDurationMs ?? null, + maxDaemonShardFileDurationMs: suiteSummaries.daemon?.maxShardFileDurationMs ?? null, shardImbalanceRatioBySuite: Object.fromEntries(Object.entries(suiteSummaries) .map(([suite, summary]) => [suite, summary.imbalanceRatio])), }, jobs: jobDurations, - reports: reportTelemetry(normalizedReports), + reports: reportDetails, }; } export function renderSummary(telemetry) { const ms = value => value === null ? "n/a" : `${(value / 60000).toFixed(2)} min`; + const count = value => value === null ? "n/a" : value; const lines = [ "## CI timing telemetry", "", ...(telemetry.telemetryUnavailable ? ["- Collection status: **unavailable**; this did not affect the quality gate."] : []), - `- Run duration observed at collection: **${ms(telemetry.run.durationMs)}**; critical path: **${ms(telemetry.run.criticalPathMs)}**`, - `- Jobs: **${telemetry.summary.jobCount}**; max execution: **${ms(telemetry.summary.maxJobExecutionMs)}**; max queue estimate: **${ms(telemetry.summary.maxJobQueueMs)}**`, - `- Failed jobs: **${telemetry.summary.failedJobCount}**; timed-out files: **${telemetry.summary.timedOutFileCount}**; leaked-process files: **${telemetry.summary.leakedProcessFileCount}**`, + `- Run duration: **${ms(telemetry.run.durationMs)}** (source: ${telemetry.run.durationSource}); completed jobs elapsed since run creation: **${ms(telemetry.run.completedJobsElapsedMs)}** (excludes in-progress jobs; not a DAG critical path).`, + `- Jobs: **${telemetry.summary.jobCount}**; max execution: **${ms(telemetry.summary.maxJobExecutionMs)}**; max start delay: **${ms(telemetry.summary.maxJobStartDelayMs)}** (includes dependency wait; measured from run start, or run creation if unavailable).`, + `- Failed jobs: **${telemetry.summary.failedJobCount}**; timed-out files: **${count(telemetry.summary.timedOutFileCount)}**; leaked-process files: **${count(telemetry.summary.leakedProcessFileCount)}** (counts from available reports: ${telemetry.summary.availableReportCount}; missing or incomplete reports do not establish zero faults across the run).`, ]; for (const [suite, data] of Object.entries(telemetry.reports.suites)) { - lines.push(`- ${suite} shards: **${data.shardCount}**; max/average file time: **${ms(data.maxShardFileDurationMs)} / ${ms(data.averageShardFileDurationMs)}**; imbalance: **${data.imbalanceRatio === null ? "n/a" : data.imbalanceRatio.toFixed(2)}x**`); + lines.push(`- ${suite} shards: **${data.shardCount}**; max/average aggregate file time: **${ms(data.maxShardFileDurationMs)} / ${ms(data.averageShardFileDurationMs)}** (aggregate file time, not wall clock); imbalance: **${data.imbalanceRatio === null ? "n/a" : data.imbalanceRatio.toFixed(2)}x**`); } lines.push("", "Per-job and per-file details are retained in the `ci-telemetry` artifact."); return `${lines.join("\n")}\n`; diff --git a/scripts/ci/ci-telemetry.test.mjs b/scripts/ci/ci-telemetry.test.mjs index e127ab9f9..352f58982 100644 --- a/scripts/ci/ci-telemetry.test.mjs +++ b/scripts/ci/ci-telemetry.test.mjs @@ -10,12 +10,13 @@ const run = { id: 42, event: "pull_request", head_sha: "abc123", + status: "completed", created_at: "2026-01-01T00:00:00Z", run_started_at: "2026-01-01T00:00:10Z", updated_at: "2026-01-01T00:05:00Z", }; -test("builds bounded run, queue, job, and shard telemetry", () => { +test("builds run, start-delay, job, and aggregate shard file telemetry", () => { const telemetry = buildTelemetry({ run, jobs: [{ name: "Daemon tests (shard 0)", status: "completed", conclusion: "success", runner_name: "macos-26", @@ -27,15 +28,67 @@ test("builds bounded run, queue, job, and shard telemetry", () => { ] }], }); assert.equal(telemetry.run.durationMs, 300000); - assert.equal(telemetry.run.criticalPathMs, 180000); - assert.equal(telemetry.jobs[0].queuedMs, 50000); + assert.equal(telemetry.run.durationSource, "updated_at"); + assert.equal(telemetry.run.completedJobsElapsedMs, 180000); + assert.equal(telemetry.jobs[0].startDelayMs, 50000); + assert.equal(telemetry.summary.maxJobStartDelayMs, 50000); assert.equal(telemetry.jobs[0].executionMs, 120000); assert.equal(telemetry.jobs[0].stepDurations[0].durationMs, 30000); assert.equal(telemetry.summary.timedOutFileCount, 1); - assert.equal(telemetry.summary.maxDaemonShardDurationMs, 3000); + assert.equal(telemetry.summary.availableReportCount, 1); + assert.equal(telemetry.summary.maxDaemonShardFileDurationMs, 3000); + assert.deepEqual(telemetry.reports.shards[0].files, [ + { file: "test/a.test.mjs", status: "passed", durationMs: 1000 }, + { file: "test/b.test.mjs", status: "timed_out", durationMs: 2000 }, + ]); assert.equal(telemetry.summary.shardImbalanceRatioBySuite.daemon, 1); assert.equal(telemetry.reports.suites.daemon.imbalanceRatio, 1); assert.match(renderSummary(telemetry), /timed-out files: \*\*1\*\*/u); + assert.match(renderSummary(telemetry), /includes dependency wait/u); + assert.match(renderSummary(telemetry), /aggregate file time, not wall clock/u); + assert.match(renderSummary(telemetry), /excludes in-progress jobs; not a DAG critical path/u); + assert.match(renderSummary(telemetry), /source: updated_at/u); + assert.equal(Object.hasOwn(telemetry.run, "criticalPathMs"), false); + assert.equal(Object.hasOwn(telemetry.jobs[0], "queuedMs"), false); + for (const field of ["maxJobQueueMs", "maxCoreShardDurationMs", "maxDaemonShardDurationMs"]) { + assert.equal(Object.hasOwn(telemetry.summary, field), false); + } +}); + +test("in-progress run duration uses the injected capture time rather than updated_at", () => { + const capturedAt = "2026-01-01T00:10:00Z"; + const telemetry = buildTelemetry({ + run: { ...run, status: "in_progress", updated_at: "2026-01-01T00:00:20Z" }, + capturedAt, + jobs: [ + { status: "completed", completed_at: "2026-01-01T00:02:00Z" }, + { status: "in_progress", started_at: "2026-01-01T00:03:00Z", completed_at: "2026-01-01T00:09:00Z" }, + ], + }); + assert.equal(telemetry.capturedAt, capturedAt); + assert.equal(telemetry.run.durationSource, "capturedAt"); + assert.equal(telemetry.run.durationMs, 600000); + assert.equal(telemetry.run.completedJobsElapsedMs, 120000); + assert.match(renderSummary(telemetry), /source: capturedAt/u); + for (const updated_at of ["not-a-date", "2026-01-01T00:09:59Z"]) { + assert.equal(buildTelemetry({ run: { ...run, status: "in_progress", updated_at }, capturedAt }).run.durationMs, 600000); + } + assert.equal(buildTelemetry({ run: { ...run, status: "queued" }, capturedAt }).run.durationMs, 600000); +}); + +test("completed run duration retains the updated_at source even after collection", () => { + const telemetry = buildTelemetry({ run, capturedAt: "2026-01-02T00:00:00Z" }); + assert.equal(telemetry.run.durationMs, 300000); + assert.equal(telemetry.run.durationSource, "updated_at"); + assert.equal(telemetry.run.completedJobsElapsedMs, null); +}); + +test("default capture time is a real collection clock", () => { + const before = Date.now(); + const telemetry = buildTelemetry({ run: { status: "in_progress", created_at: new Date(before - 1000).toISOString() } }); + const captured = Date.parse(telemetry.capturedAt); + assert.ok(captured >= before && captured <= Date.now()); + assert.equal(telemetry.run.durationMs, captured - (before - 1000)); }); test("keeps incomplete or malformed timestamps observable without inventing durations", () => { @@ -49,7 +102,118 @@ test("keeps incomplete or malformed timestamps observable without inventing dura assert.equal(telemetry.summary.failedJobCount, 1); assert.equal(telemetry.summary.maxJobExecutionMs, null); assert.deepEqual(telemetry.reports.shards, []); + assert.equal(telemetry.summary.availableReportCount, 0); + assert.equal(telemetry.summary.timedOutFileCount, null); + assert.equal(telemetry.summary.leakedProcessFileCount, null); + assert.match(renderSummary(telemetry), /timed-out files: \*\*n\/a\*\*/u); + assert.match(renderSummary(telemetry), /counts from available reports: 0/u); assert.equal(buildTelemetry({ run: { telemetry_unavailable: true } }).telemetryUnavailable, true); + assert.equal(buildTelemetry({ jobs: { telemetry_unavailable: true } }).telemetryUnavailable, true); +}); + +test("rejects invalid, reversed, and unreasonable timing intervals without clamping", () => { + for (const [started_at, completed_at] of [ + ["not-a-date", "2026-01-01T00:01:00Z"], + ["2026-01-01T00:01:00Z", "2026-01-01T00:00:00Z"], + ["2026-01-01T00:00:00Z", "2026-02-01T00:00:00Z"], + [null, "2026-01-01T00:01:00Z"], + [0, "2026-01-01T00:01:00Z"], + [{ invalid: true }, "2026-01-01T00:01:00Z"], + ]) { + const telemetry = buildTelemetry({ + run: { ...run, created_at: started_at, updated_at: completed_at }, + jobs: [{ status: "completed", started_at, completed_at, steps: [{ started_at, completed_at }] }], + }); + assert.equal(telemetry.run.durationMs, null); + assert.equal(telemetry.run.completedJobsElapsedMs, null); + assert.equal(telemetry.jobs[0].executionMs, null); + assert.equal(telemetry.jobs[0].stepDurations[0].durationMs, null); + } + for (const started_at of ["not-a-date", "2025-12-31T23:59:00Z", "2026-02-01T00:00:00Z"]) { + const telemetry = buildTelemetry({ run, jobs: [{ started_at }] }); + assert.equal(telemetry.jobs[0].startDelayMs, null); + assert.equal(telemetry.summary.maxJobStartDelayMs, null); + } + for (const capturedAt of ["bad-clock", "2025-12-31T23:59:00Z", "2026-02-01T00:00:00Z"]) { + assert.equal(buildTelemetry({ run: { ...run, status: "in_progress" }, capturedAt }).run.durationMs, null); + } + const fallback = buildTelemetry({ run: { ...run, run_started_at: "bad" }, jobs: [{ started_at: "2026-01-01T00:01:00Z" }] }); + assert.equal(fallback.jobs[0].startDelayMs, 60000); +}); + +test("retains pending and running file details and normalizes invalid file durations", () => { + const results = [ + { file: "pending.mjs", status: "pending" }, + { file: "running.mjs", status: "running" }, + { file: "timeout.mjs", status: "timed_out", durationMs: -1 }, + { file: "leak.mjs", status: "leaked_processes", durationMs: "100" }, + ...[null, NaN, Infinity, 8 * 24 * 60 * 60 * 1000].map((durationMs, index) => ({ file: `invalid-${index}.mjs`, status: "failed", durationMs })), + { file: "passed.mjs", status: "passed", durationMs: 1000 }, + ]; + const telemetry = buildTelemetry({ reports: [{ version: 1, suite: "daemon", shard: 0, complete: false, results }] }); + const shard = telemetry.reports.shards[0]; + assert.deepEqual(shard.files, results.map(result => ({ ...result, durationMs: result.status === "passed" ? 1000 : null }))); + assert.equal(shard.complete, false); + assert.equal(shard.fileCount, results.length); + assert.equal(shard.statusCounts.pending, 1); + assert.equal(shard.statusCounts.running, 1); + assert.equal(shard.passedCount, 1); + assert.equal(shard.sumFileDurationMs, 1000); + assert.equal(shard.maxFileDurationMs, 1000); + assert.equal(shard.p95FileDurationMs, 1000); + assert.equal(telemetry.summary.timedOutFileCount, 1); + assert.equal(telemetry.summary.leakedProcessFileCount, 1); + assert.match(renderSummary(telemetry), /counts from available reports: 1/u); + assert.match(renderSummary(telemetry), /missing or incomplete reports do not establish zero faults across the run/u); +}); + +test("aggregate shard durations are file sums and retain measured zero durations", () => { + const telemetry = buildTelemetry({ reports: [ + { version: 1, suite: "core", shard: 0, results: [ + { file: "a.mjs", status: "passed", durationMs: 1000 }, + { file: "b.mjs", status: "passed", durationMs: 2000 }, + ] }, + { version: 1, suite: "core", shard: 1, results: [{ file: "c.mjs", status: "passed", durationMs: 0 }] }, + { version: 1, suite: "core", shard: 2, results: [{ file: "d.mjs", status: "pending" }] }, + ] }); + assert.equal(telemetry.summary.maxCoreShardFileDurationMs, 3000); + assert.equal(telemetry.reports.shards[0].sumFileDurationMs, 3000); + assert.equal(telemetry.reports.shards[1].sumFileDurationMs, 0); + assert.equal(telemetry.reports.shards[2].sumFileDurationMs, null); + assert.deepEqual(telemetry.reports.suites.core, { + shardCount: 3, maxShardFileDurationMs: 3000, averageShardFileDurationMs: 1500, imbalanceRatio: 2, + }); +}); + +test("p95 file duration uses nearest-rank for small samples", () => { + for (const [durations, expected] of [ + [[], null], [[1000], 1000], [[2000, 1000], 2000], + [[3000, 1000, 2000], 3000], [Array.from({ length: 20 }, (_, index) => index + 1), 19], + ]) { + const telemetry = buildTelemetry({ reports: [{ version: 1, suite: "core", shard: 0, + results: durations.map((durationMs, index) => ({ file: `${index}.mjs`, status: "passed", durationMs })) }] }); + assert.equal(telemetry.reports.shards[0].p95FileDurationMs, expected); + } +}); + +test("tolerates invalid reports and malformed result, job, and step entries", () => { + const invalidReports = [null, false, "bad", {}, { version: 2, suite: "core", shard: 0, results: [] }, + { version: 1, suite: "core", shard: -1, results: [] }, { version: 1, suite: "core", shard: 0, results: null }]; + assert.equal(buildTelemetry({ reports: invalidReports }).summary.availableReportCount, 0); + for (const reports of [null, {}, "bad"]) assert.deepEqual(buildTelemetry({ reports }).reports.shards, []); + assert.doesNotThrow(() => buildTelemetry({ run: null, jobs: null })); + const telemetry = buildTelemetry({ + jobs: { jobs: [null, false, "bad", { steps: {} }, { steps: [null, false, "bad", {}] }] }, + reports: [...invalidReports, { version: 1, suite: "__proto__", shard: 0, + results: [null, false, "bad", {}, { file: "retained.mjs", status: "running" }] }], + }); + assert.equal(telemetry.jobs.length, 2); + assert.deepEqual(telemetry.jobs[0].stepDurations, []); + assert.equal(telemetry.jobs[1].stepDurations.length, 1); + assert.equal(telemetry.summary.availableReportCount, 1); + assert.deepEqual(telemetry.reports.shards[0].files, [{ file: "retained.mjs", status: "running", durationMs: null }]); + assert.equal(telemetry.reports.shards[0].sumFileDurationMs, null); + assert.equal(telemetry.reports.suites.__proto__.maxShardFileDurationMs, null); }); test("CLI reads a report directory and writes both telemetry outputs", async () => { @@ -64,14 +228,18 @@ test("CLI reads a report directory and writes both telemetry outputs", async () await writeFile(jobsPath, JSON.stringify({ jobs: [] })); await mkdir(reportsPath); await writeFile(join(reportsPath, "daemon-0.json"), JSON.stringify({ - version: 1, suite: "daemon", shard: 0, results: [], + version: 1, suite: "daemon", shard: 0, results: [{ file: "pending.mjs", status: "pending" }], })); + await writeFile(join(reportsPath, "broken.json"), "{broken"); + await writeFile(join(reportsPath, "invalid.json"), JSON.stringify({ version: 2 })); const child = spawn(process.execPath, ["scripts/ci/ci-telemetry.mjs", `--run=${runPath}`, `--jobs=${jobsPath}`, `--reports-dir=${reportsPath}`, `--output=${outputPath}`, `--summary=${summaryPath}`], { cwd: process.cwd() }); const [code] = await new Promise(resolve => child.on("close", (status, signal) => resolve([status, signal]))); assert.equal(code, 0); - assert.equal(JSON.parse(await readFile(outputPath, "utf8")).reports.shards.length, 1); + const telemetry = JSON.parse(await readFile(outputPath, "utf8")); + assert.equal(telemetry.reports.shards.length, 1); + assert.deepEqual(telemetry.reports.shards[0].files, [{ file: "pending.mjs", status: "pending", durationMs: null }]); assert.match(await readFile(summaryPath, "utf8"), /CI timing telemetry/u); } finally { await rm(directory, { recursive: true, force: true }); diff --git a/scripts/ci/runtime-workflow.test.mjs b/scripts/ci/runtime-workflow.test.mjs index 4ed59d1a2..4f39c48f2 100644 --- a/scripts/ci/runtime-workflow.test.mjs +++ b/scripts/ci/runtime-workflow.test.mjs @@ -1,5 +1,9 @@ import assert from "node:assert/strict"; +import { spawnSync } from "node:child_process"; import { readFileSync } from "node:fs"; +import { mkdir, mkdtemp, readFile, rm, writeFile } from "node:fs/promises"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; import test from "node:test"; const workflow = readFileSync(new URL("../../.github/workflows/ci.yml", import.meta.url), "utf8"); @@ -9,6 +13,19 @@ function job(id) { return match[1]; } +function telemetryStep(name) { + const match = new RegExp(`^ - name: ${name}\\n([\\s\\S]*?)(?=^ - name:|$(?![\\s\\S]))`, "mu") + .exec(job("timing-telemetry")); + assert.ok(match, name); + return match[1]; +} + +function stepCommand(name) { + const match = /^ {8}run: \|\n((?: {10}[^\n]*(?:\n|$)|\n)*)/mu.exec(telemetryStep(name)); + assert.ok(match, `Missing executable command: ${name}`); + return match[1].replace(/^ {10}/gmu, ""); +} + test("all core matrix jobs are part of the existing mandatory unit gate", () => { const source = job("unit-tests"); assert.match(source, /matrix: \$\{\{ fromJSON\(needs\.scope\.outputs\.unit-matrix\) \}\}/u); @@ -50,18 +67,80 @@ test("the aggregate verifies reports before caching only default-branch successf assert.doesNotMatch(quality, /continue-on-error/u); }); -test("quality preserves non-blocking run, job, and shard timing telemetry", () => { +test("timing telemetry is independent of the mandatory quality gate", () => { const quality = job("quality"); - assert.match(quality, /permissions:\n actions: read\n contents: read/u); - assert.match(quality, /GH_TOKEN: \$\{\{ github\.token \}\}/u); - assert.match(quality, /actions\/runs\/\$\{GITHUB_RUN_ID\}/u); - assert.match(quality, /actions\/runs\/\$\{GITHUB_RUN_ID\}\/jobs\?per_page=100/u); - assert.match(quality, /ci-telemetry\.mjs/u); - assert.match(quality, /--reports-dir=\.codex-artifacts\/ci\/reports/u); - assert.match(quality, /cat \.codex-artifacts\/ci\/ci-telemetry\.md >> "\$GITHUB_STEP_SUMMARY"/u); - assert.match(quality, /name: ci-telemetry\n include-hidden-files: true/u); - assert.match(quality, /name: Preserve CI timing telemetry\n if: always\(\)/u); - assert.match(quality, /exit 0/u); + const telemetry = job("timing-telemetry"); + assert.doesNotMatch(quality, /timing-telemetry|ci-telemetry|continue-on-error/u); + assert.match(telemetry, /^ needs: \[scope, quality\]$/mu); + assert.match(telemetry, /^ if: always\(\)$/mu); + assert.match(telemetry, /^ timeout-minutes: 3$/mu); + assert.match(telemetry, /^ continue-on-error: true$/mu); + assert.match(telemetry, /permissions:\n actions: read\n contents: read/u); + assert.match(telemetry, /GH_TOKEN: \$\{\{ github\.token \}\}/u); + assert.match(telemetry, /actions\/runs\/\$\{GITHUB_RUN_ID\}/u); + assert.match(telemetry, /\/attempts\/\$\{GITHUB_RUN_ATTEMPT\}\/jobs\?per_page=100/u); + assert.match(telemetry, /ci-telemetry\.mjs/u); + assert.match(telemetry, /--reports-dir=\.codex-artifacts\/ci\/reports/u); + assert.match(telemetry, /cat \.codex-artifacts\/ci\/ci-telemetry\.md >> "\$GITHUB_STEP_SUMMARY"/u); + assert.match(telemetry, /name: ci-telemetry\n include-hidden-files: true/u); + for (const name of ["Collect workflow timing metadata", "Render CI timing telemetry", "Preserve CI timing telemetry"]) { + assert.match(telemetryStep(name), /^ if: always\(\)\n continue-on-error: true$/mu, name); + } + const download = telemetryStep("Download available shard reports including failures"); + assert.match(download, /if: always\(\) && needs\.scope\.outputs\.execution-tier == 'complete'/u); + assert.match(download, /continue-on-error: true/u); + assert.match(download, /pattern: ci-test-report-\*/u); +}); + +test("workflow collection preserves unavailable observations on API and JSON failures", async t => { + for (const mode of ["success", "api-failure", "invalid-json", "invalid-pages"]) { + await t.test(mode, async () => { + const directory = await mkdtemp(join(tmpdir(), "ci-telemetry-workflow-")); + try { + const bin = join(directory, "bin"); + await mkdir(bin); + await writeFile(join(bin, "gh"), `#!/usr/bin/env node +if (process.env.TELEMETRY_API_MODE === "api-failure") process.exit(1); +if (process.argv.at(-1).includes("/jobs?")) { + const mode = process.env.TELEMETRY_API_MODE; + process.stdout.write(mode === "invalid-json" ? "{" : mode === "invalid-pages" ? "[{}]" : '[{"jobs":[{"id":1}]},{"jobs":[{"id":2}]}]'); +} else process.stdout.write('{"id":42}'); +`, { mode: 0o755 }); + const result = spawnSync("bash", ["--noprofile", "--norc", "-eo", "pipefail", "-c", stepCommand("Collect workflow timing metadata")], { + cwd: directory, encoding: "utf8", timeout: 10000, + env: { ...process.env, PATH: `${bin}:${process.env.PATH}`, TELEMETRY_API_MODE: mode, + GITHUB_REPOSITORY: "example/repo", GITHUB_RUN_ID: "42", GITHUB_RUN_ATTEMPT: "2" }, + }); + assert.equal(result.status, 0, result.stderr); + const jobs = JSON.parse(await readFile(join(directory, ".codex-artifacts/ci/telemetry-jobs.json"), "utf8")); + if (mode === "success") assert.deepEqual(jobs, { jobs: [{ id: 1 }, { id: 2 }] }); + else assert.deepEqual(jobs, { jobs: [], telemetry_unavailable: true }); + const run = JSON.parse(await readFile(join(directory, ".codex-artifacts/ci/telemetry-run.json"), "utf8")); + if (mode === "api-failure") assert.equal(run.telemetry_unavailable, true); + else assert.equal(run.id, 42); + } finally { + await rm(directory, { recursive: true, force: true }); + } + }); + } +}); + +test("workflow rendering preserves an unavailable artifact when the telemetry command fails", async () => { + const directory = await mkdtemp(join(tmpdir(), "ci-telemetry-render-")); + try { + await mkdir(join(directory, ".codex-artifacts/ci"), { recursive: true }); + const summary = join(directory, "summary.md"); + const result = spawnSync("bash", ["--noprofile", "--norc", "-eo", "pipefail", "-c", stepCommand("Render CI timing telemetry")], { + cwd: directory, encoding: "utf8", timeout: 10000, + env: { ...process.env, GITHUB_STEP_SUMMARY: summary }, + }); + assert.equal(result.status, 0, result.stderr); + const telemetry = JSON.parse(await readFile(join(directory, ".codex-artifacts/ci/ci-telemetry.json"), "utf8")); + assert.equal(telemetry.telemetryUnavailable, true); + assert.match(await readFile(summary, "utf8"), /Telemetry was unavailable/u); + } finally { + await rm(directory, { recursive: true, force: true }); + } }); test("complete PR history scans ignore docs-only final diffs while Draft previews stay deferred", () => { From d51e3db41b0e8ac8f642976d3e5643d8048b7372 Mon Sep 17 00:00:00 2001 From: tianxiaochannel-oss88 Date: Mon, 2 Nov 2026 09:35:08 +0800 Subject: [PATCH 3/3] test(daemon): capture node goal timeout lifecycle diagnostics --- .../channel-node-invocation-binding.test.mjs | 47 ++++---- .../node-goal-command-diagnostic.test.mjs | 105 ++++++++++++++++++ .../support/node-goal-command-diagnostic.mjs | 59 ++++++++++ 3 files changed, 192 insertions(+), 19 deletions(-) create mode 100644 packages/daemon/test/node-goal-command-diagnostic.test.mjs create mode 100644 packages/daemon/test/support/node-goal-command-diagnostic.mjs diff --git a/packages/daemon/test/channel-node-invocation-binding.test.mjs b/packages/daemon/test/channel-node-invocation-binding.test.mjs index 64eb70d39..a78f1ad5e 100644 --- a/packages/daemon/test/channel-node-invocation-binding.test.mjs +++ b/packages/daemon/test/channel-node-invocation-binding.test.mjs @@ -7,6 +7,7 @@ import { workflowExactCommandBindingRejection } from "../dist/features/runs/appr import { channelOperationPlanFingerprintV1, isChannelIntentExecutionPlanV1, nodeFunctionGoalCommand, parseNodeFunctionInvocation } from "@ling-stack/contracts"; import { executeUnifiedBashTool } from "../dist/features/runs/unified-exec.js"; import { createUnifiedExecFixture } from "./support/unified-exec-fixture.mjs"; +import { captureNodeGoalCommandDiagnostic } from "./support/node-goal-command-diagnostic.mjs"; import { createSqliteRunStore, DEFAULT_WORKSPACE_ID, toRuntimeAttemptFence } from "@ling-stack/core"; import { appendChannelItemFixture } from "../../core/test/channel-conversation-fixture.mjs"; import { createDelegatedStepRequirement } from "../dist/features/channels/workflow-step-requirement.js"; @@ -99,31 +100,39 @@ test("Host-generated Node commands really invoke ESM/CJS exports and retain fail const task = { id: "node_goal_task", title: "Node goal fixture", prompt: "Execute only temporary fixture functions" }; const f = createUnifiedExecFixture(t, cwd, task, "node_goal_run"); let sequence = 0; + const diagnostics = []; const execute = async (modulePath, invocation) => { const command = nodeFunctionGoalCommand({ modulePath, invocation }); assert.ok(command); - const result = await executeUnifiedBashTool({ ...f, - request: { toolCallId: `node-goal-${++sequence}`, toolName: "bash", cwd, task, input: { command, timeoutMs: 4000 } }, - appendAndMaybeStream: (type, data) => f.store.appendEvent(f.run.id, type, data) }); + const result = await captureNodeGoalCommandDiagnostic({ sequence: ++sequence, timeoutMs: 4000, + record: diagnostic => diagnostics.push(diagnostic), + execute: () => executeUnifiedBashTool({ ...f, + request: { toolCallId: `node-goal-${sequence}`, toolName: "bash", cwd, task, input: { command, timeoutMs: 4000 } }, + appendAndMaybeStream: (type, data) => f.store.appendEvent(f.run.id, type, data) }) }); assert.equal(result.details.unifiedExec.command.command, command); assert.equal(result.details.unifiedExec.runId, f.run.id); return result.details.unifiedExec; }; - await writeFile(join(cwd, "proof.mjs"), 'export const formatProof = async value => "proof:" + value;'); - let result = await execute("proof.mjs", 'formatProof("7319")'); - assert.equal(result.status, "succeeded"); assert.equal(result.stdout.preview, "proof:7319\n"); - await writeFile(join(cwd, "proof.cjs"), 'module.exports = { formatProof: value => "common:" + value };'); - result = await execute("proof.cjs", 'formatProof("7319")'); - assert.equal(result.status, "succeeded"); assert.equal(result.stdout.preview, "common:7319\n"); - await writeFile(join(cwd, "quoted '# %.mjs"), "export const echo = value => value;"); - result = await execute("quoted '# %.mjs", `echo("'$(touch must-not-exist)")`); - assert.equal(result.status, "succeeded"); assert.equal(result.stdout.preview, "'$(touch must-not-exist)\n"); - await assert.rejects(readFile(join(cwd, "must-not-exist")), { code: "ENOENT" }); - result = await execute("proof.mjs", "missing()"); - assert.equal(result.status, "failed"); assert.notEqual(result.exitCode, 0); assert.match(result.stderr.preview, /missing export/); - await writeFile(join(cwd, "throwing.mjs"), 'export const formatProof = async () => { throw Error("fixture rejection"); };'); - result = await execute("throwing.mjs", 'formatProof("7319")'); - assert.equal(result.status, "failed"); assert.notEqual(result.exitCode, 0); assert.match(result.stderr.preview, /fixture rejection/); - assert.deepEqual(f.store.listHostCommandWriteBlockers(cwd), []); + try { + await writeFile(join(cwd, "proof.mjs"), 'export const formatProof = async value => "proof:" + value;'); + let result = await execute("proof.mjs", 'formatProof("7319")'); + assert.equal(result.status, "succeeded"); assert.equal(result.stdout.preview, "proof:7319\n"); + await writeFile(join(cwd, "proof.cjs"), 'module.exports = { formatProof: value => "common:" + value };'); + result = await execute("proof.cjs", 'formatProof("7319")'); + assert.equal(result.status, "succeeded"); assert.equal(result.stdout.preview, "common:7319\n"); + await writeFile(join(cwd, "quoted '# %.mjs"), "export const echo = value => value;"); + result = await execute("quoted '# %.mjs", `echo("'$(touch must-not-exist)")`); + assert.equal(result.status, "succeeded"); assert.equal(result.stdout.preview, "'$(touch must-not-exist)\n"); + await assert.rejects(readFile(join(cwd, "must-not-exist")), { code: "ENOENT" }); + result = await execute("proof.mjs", "missing()"); + assert.equal(result.status, "failed"); assert.notEqual(result.exitCode, 0); assert.match(result.stderr.preview, /missing export/); + await writeFile(join(cwd, "throwing.mjs"), 'export const formatProof = async () => { throw Error("fixture rejection"); };'); + result = await execute("throwing.mjs", 'formatProof("7319")'); + assert.equal(result.status, "failed"); assert.notEqual(result.exitCode, 0); assert.match(result.stderr.preview, /fixture rejection/); + assert.deepEqual(f.store.listHostCommandWriteBlockers(cwd), []); + } catch (error) { + for (const diagnostic of diagnostics) t.diagnostic(JSON.stringify(diagnostic)); + throw error; + } }); test("recomputed plan fingerprints cannot detach generated commands from their accepted goal", async t => { diff --git a/packages/daemon/test/node-goal-command-diagnostic.test.mjs b/packages/daemon/test/node-goal-command-diagnostic.test.mjs new file mode 100644 index 000000000..b5438477b --- /dev/null +++ b/packages/daemon/test/node-goal-command-diagnostic.test.mjs @@ -0,0 +1,105 @@ +import assert from "node:assert/strict"; +import { spawn } from "node:child_process"; +import { channel, hasSubscribers } from "node:diagnostics_channel"; +import { EventEmitter } from "node:events"; +import test from "node:test"; +import { captureNodeGoalCommandDiagnostic } from "./support/node-goal-command-diagnostic.mjs"; + +test("command diagnostics retain failure evidence but exclude command, environment and output payloads", async () => { + const secret = "private-diagnostic-sentinel"; + const result = { status: "timed_out", startedAt: "2026-11-02T00:00:00Z", endedAt: "2026-11-02T00:00:04Z", + durationMs: 4001, signal: "SIGTERM", timedOut: true, cancelled: false, + command: { command: secret }, cwd: secret, environmentSummary: { keys: [secret], extraEnv: { TOKEN: secret } }, + processObservation: { scope: "process_group", leaderExited: true, stdioClosed: true, + descendants: "unverified", stopReason: "timeout", settledBy: "close", signalFailures: ["SIGTERM:group:EPERM"], private: secret }, + stdout: { byteCount: 0, truncated: false, preview: secret, artifactId: secret }, + stderr: { byteCount: 12, truncated: true, preview: secret }, artifacts: [{ path: secret }], reason: secret }; + const handled = { details: { unifiedExec: result, private: secret }, content: [{ text: secret }] }; + const records = []; + assert.equal(await captureNodeGoalCommandDiagnostic({ sequence: 1, timeoutMs: 4000, + execute: async () => handled, record: value => records.push(value) }), handled); + assert.equal(records.length, 1); + const diagnostic = records[0]; + assert.equal(diagnostic.kind, "node_goal_command_diagnostic_v1"); + assert.equal(diagnostic.timeoutMs, 4000); + assert.equal(diagnostic.result.status, "timed_out"); + assert.equal(diagnostic.result.durationMs, 4001); + assert.equal(diagnostic.result.exitCode, null); + assert.equal(diagnostic.result.signal, "SIGTERM"); + assert.deepEqual(diagnostic.result.processObservation, { scope: "process_group", leaderExited: true, + stdioClosed: true, descendants: "unverified", stopReason: "timeout", settledBy: "close", signalFailures: ["SIGTERM:group:EPERM"] }); + assert.deepEqual(diagnostic.result.stdout, { byteCount: 0, truncated: false }); + assert.deepEqual(diagnostic.result.stderr, { byteCount: 12, truncated: true }); + assert.equal(JSON.stringify(diagnostic).includes(secret), false); +}); + +test("diagnostics distinguish no-start denial from a returned process result", async () => { + let diagnostic; + await captureNodeGoalCommandDiagnostic({ sequence: 2, timeoutMs: 4000, + execute: async () => ({ details: { unifiedExec: { status: "failed", denied: true, reason: "private denial" } } }), + record: value => { diagnostic = value; } }); + assert.equal(diagnostic.returned, true); + assert.equal(diagnostic.result.denied, true); + assert.equal(diagnostic.result.processObservation, null); + assert.equal(diagnostic.result.durationMs, null); + assert.deepEqual(diagnostic.processes, []); + assert.equal(JSON.stringify(diagnostic).includes("private denial"), false); +}); + +test("real process lifecycle timings do not consume or alter output", async () => { + const subscribed = hasSubscribers("child_process"); + let diagnostic; + let stdout = "", stderr = ""; + await captureNodeGoalCommandDiagnostic({ sequence: 3, timeoutMs: 4000, + execute: () => new Promise((resolve, reject) => { + const child = spawn(process.execPath, ["-e", 'process.stdout.write("fixture-out");process.stderr.write("fixture-err");']); + child.stdout.on("data", chunk => { stdout += chunk; }); + child.stderr.on("data", chunk => { stderr += chunk; }); + child.once("error", reject); + child.once("close", code => { + if (code === 0) resolve({}); + else reject(new Error(`fixture exited with code ${code}`)); + }); + }), record: value => { diagnostic = value; } }); + assert.equal(hasSubscribers("child_process"), subscribed); + assert.equal(stdout, "fixture-out"); + assert.equal(stderr, "fixture-err"); + assert.equal(diagnostic.processes.length, 1); + const timing = diagnostic.processes[0]; + for (const key of ["createdMs", "spawnedMs", "firstStdoutMs", "firstStderrMs", "exitMs", "closeMs"]) { + assert.equal(typeof timing[key], "number", key); + assert.ok(timing[key] >= 0, key); + } + assert.ok(timing.createdMs <= timing.spawnedMs); + assert.ok(timing.spawnedMs <= timing.firstStdoutMs); + assert.ok(timing.spawnedMs <= timing.firstStderrMs); + assert.ok(timing.exitMs <= timing.closeMs); + assert.ok(timing.closeMs <= diagnostic.elapsedMs); + assert.equal(timing.exitCode, 0); + assert.equal(timing.signal, null); + assert.equal(JSON.stringify(diagnostic).includes("fixture-out"), false); + assert.equal(JSON.stringify(diagnostic).includes("fixture-err"), false); +}); + +test("thrown execution keeps its original error and detaches every diagnostic listener", async () => { + const subscribed = hasSubscribers("child_process"); + const child = Object.assign(new EventEmitter(), { stdout: new EventEmitter(), stderr: new EventEmitter() }); + const error = new Error("original private error"); + let diagnostic; + await assert.rejects(captureNodeGoalCommandDiagnostic({ sequence: 4, timeoutMs: 4000, + execute: async () => { + channel("child_process").publish({ process: child }); + child.emit("spawn"); + child.emit("error", { code: "ENOENT", message: "private spawn error" }); + throw error; + }, record: value => { diagnostic = value; } }), cause => cause === error); + assert.equal(hasSubscribers("child_process"), subscribed); + for (const emitter of [child, child.stdout, child.stderr]) assert.deepEqual(emitter.eventNames(), []); + assert.equal(diagnostic.returned, false); + assert.equal(diagnostic.result.status, null); + assert.equal(diagnostic.processes[0].errorCode, "ENOENT"); + assert.equal(diagnostic.processes[0].firstStdoutMs, null); + assert.equal(diagnostic.processes[0].exitMs, null); + assert.equal(diagnostic.processes[0].closeMs, null); + assert.equal(JSON.stringify(diagnostic).includes("private"), false); +}); diff --git a/packages/daemon/test/support/node-goal-command-diagnostic.mjs b/packages/daemon/test/support/node-goal-command-diagnostic.mjs new file mode 100644 index 000000000..9a5509c20 --- /dev/null +++ b/packages/daemon/test/support/node-goal-command-diagnostic.mjs @@ -0,0 +1,59 @@ +import { subscribe, unsubscribe } from "node:diagnostics_channel"; + +/** Observe the real producer without replacing spawn or retaining command/output text. */ +export async function captureNodeGoalCommandDiagnostic({ sequence, timeoutMs, execute, record }) { + const started = performance.now(); + const elapsed = () => performance.now() - started; + const processes = []; + const cleanup = []; + const listen = (emitter, event, callback) => { + emitter?.once(event, callback); + if (emitter) cleanup.push(() => emitter.removeListener(event, callback)); + }; + const onChild = ({ process: child }) => { + const timing = { createdMs: elapsed(), spawnedMs: null, firstStdoutMs: null, firstStderrMs: null, + exitMs: null, closeMs: null, exitCode: null, signal: null, errorCode: null }; + processes.push(timing); + listen(child, "spawn", () => { + timing.spawnedMs = elapsed(); + listen(child.stdout, "data", () => { timing.firstStdoutMs = elapsed(); }); + listen(child.stderr, "data", () => { timing.firstStderrMs = elapsed(); }); + }); + listen(child, "exit", (code, signal) => { timing.exitMs = elapsed(); timing.exitCode = code; timing.signal = signal; }); + listen(child, "close", () => { timing.closeMs = elapsed(); }); + listen(child, "error", error => { + timing.errorCode = typeof error.code === "string" && /^[A-Z0-9_]{1,40}$/.test(error.code) ? error.code : "unknown"; + }); + }; + let handled; + let returned = false; + subscribe("child_process", onChild); + try { + handled = await execute(); + returned = true; + return handled; + } finally { + const elapsedMs = elapsed(); + unsubscribe("child_process", onChild); + for (const detach of cleanup) detach(); + const result = handled?.details?.unifiedExec; + const observation = result?.processObservation; + record({ kind: "node_goal_command_diagnostic_v1", sequence, timeoutMs, + nodeVersion: process.version, platform: process.platform, arch: process.arch, + elapsedMs, returned, processes, + result: { + status: result?.status ?? null, denied: result?.denied === true, + startedAt: result?.startedAt ?? null, endedAt: result?.endedAt ?? null, + durationMs: result?.durationMs ?? null, exitCode: result?.exitCode ?? null, signal: result?.signal ?? null, + timedOut: result?.timedOut ?? null, cancelled: result?.cancelled ?? null, + processObservation: observation ? { + scope: observation.scope, leaderExited: observation.leaderExited, stdioClosed: observation.stdioClosed, + descendants: observation.descendants, stopReason: observation.stopReason ?? null, + settledBy: observation.settledBy, signalFailures: [...observation.signalFailures], + } : null, + stdout: { byteCount: result?.stdout?.byteCount ?? null, truncated: result?.stdout?.truncated ?? null }, + stderr: { byteCount: result?.stderr?.byteCount ?? null, truncated: result?.stderr?.truncated ?? null }, + }, + }); + } +}