Skip to content

test: de-flake internal/metrics timing-sensitive tests - #788

Open
kinyoklion wants to merge 1 commit into
v9from
rlamb/sdk-2839/deflake-metrics-timing-tests
Open

test: de-flake internal/metrics timing-sensitive tests#788
kinyoklion wants to merge 1 commit into
v9from
rlamb/sdk-2839/deflake-metrics-timing-tests

Conversation

@kinyoklion

@kinyoklion kinyoklion commented Jul 31, 2026

Copy link
Copy Markdown
Member

Ticket: SDK-2839

The internal/metrics tests measured real wall-clock sleeps and asserted durations within tight tolerances, which fails intermittently under CI runner scheduling jitter. From a survey of the last 300 CI runs, TestNonoverlappingStreams alone failed 5 times across unrelated branches (including v9 push runs), e.g.:

--- FAIL: TestNonoverlappingStreams (0.05s)
    Error: Max difference between 40 and 46 allowed is 5, but difference was -6

TestCapturesSimpleStreamDuration, TestStreamWithoutDisconnect, and the TestRelayMetricsCollector subtest the event start time still shifts when events are not sent (which raced the 1ms flush ticker against a 1ms sleep) have also flaked.

Changes

  • environmentMetricUsage takes an injectable time source (NewEnvironmentMetricUsage behavior is unchanged; it uses time.Now). Usage activity, flush, and shutdown messages are stamped with a timestamp when they are handed off — before crossing into the processing goroutine — so a test that advances a fake clock between messages observes exact durations with no race against the processing goroutine.
  • RelayMetricsCollector likewise takes an injectable time source via newRelayMetricsCollectorWithTimeSource.
  • The timing-sensitive tests advance a shared fakeClock test helper instead of sleeping, and assert exact durations (assert.Equal(int64(40), ...)) instead of InDeltaf tolerances.
  • The collector's start-time-shift subtest now drives the interval shift with an explicit empty flush and asserts exact start/end dates, instead of racing the background ticker.

For the production code path the only behavioral difference is that a usage message's timestamp is captured at hand-off rather than when the processing goroutine dequeues it — if anything slightly more accurate, since it no longer includes queueing delay.

Verification

  • go test -race -count=3 ./internal/metrics/ green.
  • The converted tests pass 100 consecutive runs with -race while the machine is under full CPU load (previously the InDelta assertions failed readily under contention).

Note

Low Risk
Changes are mostly test infrastructure; production usage timestamps move slightly earlier (at enqueue), which is a minor reporting nuance, not security- or data-critical logic.

Overview
Stabilizes internal/metrics tests that previously slept on the wall clock and used loose duration tolerances, which flaked under CI scheduling.

Relay metrics: RelayMetricsCollector now uses an injectable now (production still uses time.Now via newRelayMetricsCollectorWithTimeSource). The interval-shift subtest drives an empty flush with a fakeClock and asserts exact StartDate/EndDate instead of racing the background ticker.

Usage metrics: environmentMetricUsage accepts the same injectable clock in tests. Activity, flush, and shutdown messages carry a timestamp stamped when the message is handed to the channel (before the processing goroutine runs); flushInternal takes that time instead of calling time.Now inside the goroutine. Stream-duration tests advance fakeClock and use assert.Equal on TotalStreamMs instead of InDeltaf.

A shared fakeClock test helper replaces real sleeps in the converted tests.

Reviewed by Cursor Bugbot for commit e7b550b. Bugbot is set up for automated code reviews on this repo. Configure here.

The usage-metrics and relay-metrics-collector tests measured real
wall-clock sleeps and asserted durations within tight tolerances
(e.g. +/-5ms), which fails intermittently under CI scheduling jitter.

Inject a controllable time source into environmentMetricUsage and
RelayMetricsCollector. Usage activity messages are now stamped with a
timestamp when they are handed off, before crossing into the processing
goroutine, so tests that advance a fake clock between messages observe
exact durations. The timing-sensitive tests now advance a fake clock
and assert exact values instead of sleeping.

SDK-2839
@kinyoklion
kinyoklion marked this pull request as ready for review July 31, 2026 22:42
@kinyoklion
kinyoklion requested a review from a team as a code owner July 31, 2026 22:42

@cursor cursor Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

Cursor Bugbot has reviewed your changes using default effort and found 1 potential issue.

Fix All in Cursor

❌ Bugbot Autofix is OFF. To automatically fix reported issues with cloud agents, have a team admin enable autofix in the Cursor dashboard.

Reviewed by Cursor Bugbot for commit e7b550b. Configure here.

Comment thread internal/metrics/usage.go
select {
case <-ticker.C:
e.flushInternal()
e.flushInternal(e.now())

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

Handoff timestamps race with flushes

Low Severity

Activity timestamps are sampled in usageActivityMessage before the send, while ticker flushes sample e.now() after winning select. If a connect/disconnect is stamped and then preempted—or loses select to a ready ticker—flushInternal can reset firstActive to a later time before that message is applied, so lastActive ends up before firstActive and streamingDurationAdjustment goes negative, producing a bad follow-up relayUsage event.

Additional Locations (2)
Fix in Cursor Fix in Web

Reviewed by Cursor Bugbot for commit e7b550b. Configure here.

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.

1 participant