Skip to content

test: give telemetry probes their subprocess budget - #120

Open
JasonBuildAI wants to merge 1 commit into
CopilotKit:mainfrom
JasonBuildAI:fix/telemetry-probe-timeout
Open

JasonBuildAI wants to merge 1 commit into
CopilotKit:mainfrom
JasonBuildAI:fix/telemetry-probe-timeout

Conversation

@JasonBuildAI

Copy link
Copy Markdown

What this changes

tests/telemetry.test.ts was timing out intermittently, and I think the cause
is a mismatch between two numbers already in the file.

Seven of its eight tests each boot a fresh Node subprocess with --import tsx
to load src/server/platform.ts, so that the SDK's telemetry singleton starts
clean and observes one environment at a time. captureRuntime() gives that
subprocess a 15 s budget:

timeout: 15000,

but Vitest ends the test itself after its 5 s default testTimeout, and the
repo doesn't raise that anywhere (no test block in vite.config.ts). So a
subprocess that is still comfortably inside the budget it was given gets cut
off by the test runner, and the failure is a bare Test timed out in 5000ms.

I set testTimeout to 20 s for this file only. The number is deliberately
larger than the subprocess budget rather than equal to it: if a probe genuinely
hangs, execFile still trips first and reports that, instead of the test
timeout firing first on a merely slow start.

How I measured it

Run in isolation, all eight tests pass, but the margin over the 5 s cap is thin:

respects COPILOTKIT_TELEMETRY_SAMPLE_RATE=0      3056ms
respects DO_NOT_TRACK=1                          3224ms
respects COPILOTKIT_TELEMETRY_DISABLED=1         3256ms
...
sends OpenDots runtime metadata ... without the project key   4272ms

Run as part of the full suite, on an unmodified main checkout, two of them
cross the line:

FAIL tests/telemetry.test.ts > sends OpenDots runtime metadata with CLI identity and without the project key
FAIL tests/telemetry.test.ts > respects DO_NOT_TRACK=true
Error: Test timed out in 5000ms.
Test Files  1 failed | 47 passed (48)
Tests       2 failed | 300 passed (302)

That's contention, not a wrong assertion: the tsx cold compile is slow on its
own, and 48 files are competing for the CPU at the same time. I also noticed
@Adii0906 ran into the same thing in #100 and mentioned "3 unrelated timeouts
remain in telemetry.test.ts", so I don't think it's my machine alone.

Honest scope: I could not reach the Actions API from here, so I can't say
whether CI on ubuntu is red right now. It may well pass on a fast runner today.
What I can say is that the tests run at roughly 65-85% of their allowed time,
which is not much headroom, and the file already budgets the subprocess 3x
longer than it budgets the test.

The change

One file, five added lines, no production code:

  • import vi alongside expect and it;
  • vi.setConfig({ testTimeout: 20000 }) at the top of the file;
  • a short comment recording why 20 s and where it comes from.

I first passed the timeout as an argument to each it() call, but the long
test-name strings then push the calls past 80 columns and Prettier reflows the
whole blocks, which turns a 5-line change into a 74-line diff. Keeping it at
file scope via vi.setConfig avoids that churn. The tests that only read
compose.yml inherit the same budget and are unaffected; the two opt-out
checks still assert an empty capture, so a probe that quietly stops emitting
events would still fail for the right reason.

Verification

On Node 24, matching CI's node-version and the repo's engines field, with
branch = upstream/main + 1 commit (no rebase needed):

  • npm run check-format - Prettier clean
  • npm run lint - clean
  • npm run typecheck - clean
  • npm test - 48 files, 302 tests passed (run twice, same result; was 2 failed | 300 passed on unmodified main)
  • npm run build - built successfully

The probes still intercept globalThis.fetch in the subprocess, so nothing here
sends live telemetry or needs a network or an Intelligence connection.

Each probe boots a fresh tsx process that captureRuntime already lets run for 15 s, but Vitest kills the test at its 5 s default first. Individually the probes take 3.2-4.3 s, so a full-suite run on a clean main checkout failed 2 of them with "Test timed out in 5000ms"; under this budget the suite is 302/302.

@NathanTarbert NathanTarbert left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks @JasonBuildAI, nice catch reading those two numbers side by side. With captureRuntime allowing each probe 15 seconds and Vitest stopping at 5, the outcome depends on how busy the machine is. Under load here, main came within a quarter second of the cap. Setting the file's timeout above the subprocess budget keeps a real hang reported by execFile rather than as a test timeout, which is the right way round.

Looks good to me.

@JasonBuildAI

Copy link
Copy Markdown
Author

Thanks @JasonBuildAI, nice catch reading those two numbers side by side. With captureRuntime allowing each probe 15 seconds and Vitest stopping at 5, the outcome depends on how busy the machine is. Under load here, main came within a quarter second of the cap. Setting the file's timeout above the subprocess budget keeps a real hang reported by execFile rather than as a test timeout, which is the right way round.

Looks good to me.

Thanks Nathan, really appreciate the review — and for timing this on a clean main. Good to know it lands within a quarter second of the cap there too.
One thing: CI is still sitting at action_required on this fork PR, so I can't trigger it myself. Would you mind hitting Approve and run so the checks can go green before this merges? Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants