fix: wait for full completion before asserting in tests by eric-hughes-coder · Pull Request #30885 · coder/coder

eric-hughes-coder · 2026-10-16T00:06:02Z

Fixes the TestServer_Metrics/Forwarding flake reported in PLAT-609 and, in addition, other defects similar to it.

Testing defects

The Original

TestServer_Metrics/Forwarding waited for batches_dropped_total and then asserted on logs_dropped_total. The forwarder updates those two counters separately, on adjacent lines, so a read between them sees the first updated and the second not. CI caught exactly that window: expected 2, actual 0 at proxy_test.go:780. Each counter is atomic on its own, so the race detector reports nothing.

The Additional

The fallacy of the original is a de facto assumption that sequential updates are atomic as a group. The defect arose from not taking into account that they are atomic individually. The test asserted before the work was completed. A repo-wide sweep for related metrics written together found similar mistakes in other tests:

Live races: all three phases of TestServer_Metrics/Forwarding and TestServer_Metrics/BufferFull in agent/boundarylogproxy, and TestMetadataBatcher_DropsWhenFull, which waited for the update channel to empty although the final flush runs after that.
Correct only because of the current implementation's ordering: TestMetrics_TokenUseCount in aibridge, four tests in coderd/agentapi/metadatabatcher, and TestAgentStatsSessionCounts in coderd/prometheusmetrics. These pass today but would start failing if the code under test reordered its work.

Fixes

All tests the sweep found were fixed. Each test now waits for every value it asserts before asserting it. Where a value is already non-zero from earlier work, or legitimately zero, the wait is for the final value rather than for a change, and several tests use require.EventuallyWithT so the wait and the assertion are one step. Two Forwarding phases gain assertions on values they already waited for: batches_dropped_total == 1 in phase 1, and the reporter's recorded request count in phase 2.

Two phases of TestAgentStatsSessionCounts assert that the counts did not change. No wait on an unchanged value can show that the collection cycle ran, so they keep waiting on the execution histogram, and a comment at that wait names the dependency.

Each fix was checked by temporarily blocking or reordering the code under test between the relevant writes: the old test failed on every run and the new one passed.

Documentation

As a guard against recurrence of defects of this kind, we add the following documentation targeted mostly at agents. The material in TESTING.md provides guidance about how to write such a test correctly in the first place. That in AGENT_FAILURES.md describes how to recognize the symptoms of this class of test failure, should they arise.

.claude/docs/TESTING.md: new section "Wait for Full Completion before Asserting", covering waits on one value with assertions on another, Prometheus metrics in particular, and assertions that nothing changed.
.claude/docs/AGENT_FAILURES.md: a catalog entry for the symptom.
coderd/coderdtest/promhelp: doc comments noting that each helper call is a separate gather.

Generated with Claude Code under the direction of @eric-hughes-coder.

Catalogs the flake class behind PLAT-609: a test waits on one value, then asserts another that is updated separately. Refs PLAT-609 Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

Adds a TESTING.md section stating that a wait covers only the condition it polls, with Prometheus metrics as the leading case, and points the failure catalog entry at it. Refs PLAT-609 Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

The package comment states that values from separate helper calls need not agree and refers to the TESTING.md section on waiting for one value and asserting another. MetricValue and its wrappers point back to it. Refs PLAT-609 Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

TestServer_Metrics/Forwarding waited for batches_dropped_total and then asserted logs_dropped_total, which the forwarder updates separately afterward. The poll now waits for both, and both are asserted. Refs PLAT-609 Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

Phase 3 of TestServer_Metrics/Forwarding waited for the boundary_channel_full series and then asserted boundary_batch_full, which the reader goroutine updates separately afterward. The poll now waits for both. The TESTING.md citation moves to the comment on the Forwarding subtest, since it applies to every phase. Refs PLAT-609 Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

Phase 2 of TestServer_Metrics/Forwarding waited for the fake reporter to record the logs and then asserted batches_forwarded_total, which the forwarder increments only after ReportBoundaryLogs returns. The poll now waits for both, and both are asserted. Refs PLAT-609 Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

TestServer_Metrics/BufferFull waited for batches_dropped_total and then asserted logs_dropped_total, which bufferLogs updates separately afterward. The poll now waits for both, and both are asserted exactly. Refs PLAT-609 Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

TestMetrics_TokenUseCount waited for the input series and then asserted the others, which are recorded separately and, for Anthropic streaming, across two records. It passed only because the handler waits for its recorders before the response ends. The poll now waits for every series to reach its expected value, so the test no longer depends on that ordering. Refs PLAT-609 Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

Four metadata batcher tests waited for BatchesTotal and then asserted MetadataTotal. They passed only because the flush writes MetadataTotal first, and in TestMetadataBatcher because the capacity timer is reset after the flush. The polls now wait for both metrics, and both are asserted. Refs PLAT-609 Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

Renames the TESTING.md section to "Wait for Full Completion before Asserting" and states the general rule, with waiting on one value and asserting another as one case and asserting that a value is unchanged as another. Updates every citation of the old heading: the failure catalog link, the promhelp package comment, and the test comments. Refs PLAT-609 Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

TestAgentStatsSessionCounts waited for the execution histogram and then asserted the session counts, which AgentStats commits separately before recording the histogram. The first phase now waits for the counts themselves. counts takes a require.TestingT so it can run inside EventuallyWithT. Refs PLAT-609 Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

The phases of TestAgentStatsSessionCounts that assert unchanged session counts can only wait on the execution histogram. The comment at that wait now states that they rely on AgentStats recording it after committing the gauges. Refs PLAT-609 Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

The last phase of TestAgentStatsSessionCounts waited for the execution histogram and then asserted the updated session counts. It now waits for the counts themselves, as the first phase does. Refs PLAT-609 Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

TestMetadataBatcher_DropsWhenFull waited for the update channel to empty and then asserted the flush metrics. The channel empties when the run loop receives the last entry, before the final flush runs. The test now waits for the flush metrics to reach their final values. Refs PLAT-609 Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

Each comment already states why its wait covers what it asserts, and agents load TESTING.md every session. The citation stays at the one wait that deliberately relies on a value other than the one asserted, in TestAgentStatsSessionCounts, and in the promhelp package comment. Refs PLAT-609 Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

linear-code · 2026-10-16T00:06:08Z

PLAT-609

…forwarding

nickvigilante

I did a manual verification of the Markdown files in this PR along with an agent review of everything, and it LGTM. I attached some of the feedback here from my agent.

nickvigilante · 2026-10-16T13:57:09Z

@@ -655,9 +662,13 @@ func TestMetadataBatcher_Deduplication(t *testing.T) {
 			clock.Advance(defaultMetadataFlushInterval).MustWait(ctx)

 			// Verify flush occurred with correct number of entries


Nit: the existing comment has no period and runs straight into the new one, so the two read as one sentence. Same pattern on lines 763 and 1017.

Suggested change

// Verify flush occurred with correct number of entries

// Verify flush occurred with correct number of entries.

//

nickvigilante · 2026-10-16T13:57:09Z

 	testutil.Eventually(ctx, t, func(ctx context.Context) bool {
-		return float64(1) == prom_testutil.ToFloat64(b.Metrics.BatchesTotal.WithLabelValues(flushCapacity))
+		return prom_testutil.ToFloat64(b.Metrics.BatchesTotal.WithLabelValues(flushCapacity)) > 0 &&
+			prom_testutil.ToFloat64(b.Metrics.MetadataTotal) == 507


Nit: 507 now appears in both the poll and the require.Equal on line 405, and the poll already waits for that exact value, so line 405 can't fail. A named constant (or a short note that it's the earlier flushes' 7 plus defaultMetadataBatchSize) would make the number easier to maintain if the earlier flushes change.

The test on 405 is indeed redundant. Reworked.

Caught that on another test. Didn't on this one.

nickvigilante · 2026-10-16T13:57:09Z

@@ -750,9 +761,12 @@ func TestMetadataBatcher_TimestampOrdering(t *testing.T) {
 	psCap.requireContainsAll([]uuid.UUID{agent})

 	// Verify only 1 entry was flushed (newest timestamp wins)


Same as above.

Suggested change

// Verify only 1 entry was flushed (newest timestamp wins)

// Verify only 1 entry was flushed (newest timestamp wins).

//

nickvigilante · 2026-10-16T13:57:09Z

+// intermittently. See "Wait for Full Completion before Asserting" in
+// .claude/docs/TESTING.md.


Optional: the explanation in lines 4-7 already stands on its own. Pointing a Go package doc at .claude/docs/TESTING.md is unusual, since that path means nothing on pkg.go.dev or in an IDE hover. Fine to keep for a test-only package, but you could also drop the pointer and leave the cross-reference to the AGENT_FAILURES.md entry, which already links back to this package.

I'm leaving this as-is. It's a compromise.

What's really missing is a human-audience version of the potential testing hazard. I picked the citation as a substitute. The downside of writing a longer version is dual maintenance, because specific guidance for agents needs to be short.

nickvigilante · 2026-10-16T13:57:09Z

@@ -1001,8 +1015,11 @@ func TestMetadataBatcher_ConcurrentAddsToSameAgent(t *testing.T) {
 	psCap.requireContainsAll([]uuid.UUID{agentID})

 	// Verify exactly 3 unique keys were flushed


Same as above.

Suggested change

// Verify exactly 3 unique keys were flushed

// Verify exactly 3 unique keys were flushed.

//

nickvigilante · 2026-10-16T13:57:09Z

 					t.Fatal(ctx.Err())
 				}
 				polls++
+				// The histogram sample is the only signal that the collector


Not blocking, and this comment already names the dependency well. One thing worth spelling out about the failure mode: if AgentStats ever moved timer.ObserveDuration() ahead of the Commit() calls (prometheusmetrics.go around lines 660-669), phases 1 and 4 would still be correct because of the new EventuallyWithT. Phases 2 and 3 ("must retain the last snapshot") would keep passing too, but without proving anything, because they would read the counts before the cycle finished. A reader may assume a reorder makes the test fail loudly. It doesn't for those two phases, so it might be worth saying so here.

Added a sentence to that effect.

nickvigilante · 2026-10-16T13:57:09Z

+			counts := func(t require.TestingT) map[string]float64 {
 				metrics, err := registry.Gather()


Nit: switching the parameter to require.TestingT dropped t.Helper(), so failures from the require calls in here now report this closure's line instead of the caller's. *testing.T implements Helper() and *assert.CollectT does not, so a type assertion keeps both working:

Suggested change

counts := func(t require.TestingT) map[string]float64 {

metrics, err := registry.Gather()

counts := func(t require.TestingT) map[string]float64 {

if h, ok := t.(interface{ Helper() }); ok {

h.Helper()

}

metrics, err := registry.Gather()

Ends each existing "Verify" comment with a period and joins it with the new explanation. Folds the TestMetadataBatcher flush 4 poll and its duplicate assertions into one EventuallyWithT, writing 507 as the 7 earlier entries plus defaultMetadataBatchSize. Notes that the unchanged count phases of TestAgentStatsSessionCounts would pass vacuously if the histogram moved before the commits, and restores t.Helper in counts. Refs PLAT-609 Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

eric-hughes-coder and others added 15 commits October 14, 2026 22:34

docs(.claude/docs): add wait-on-one, assert-another failure entry

01bf987

Catalogs the flake class behind PLAT-609: a test waits on one value, then asserts another that is updated separately. Refs PLAT-609 Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

eric-hughes-coder requested a review from nickvigilante as a code owner October 16, 2026 00:06

github-actions Bot assigned eric-hughes-coder Oct 16, 2026

Merge branch 'main' into erichughes/plat-609-flake-testserver_metrics…

75b56d8

…forwarding

nickvigilante approved these changes Oct 16, 2026

View reviewed changes

		@@ -655,9 +662,13 @@ func TestMetadataBatcher_Deduplication(t *testing.T) {
		clock.Advance(defaultMetadataFlushInterval).MustWait(ctx)

		// Verify flush occurred with correct number of entries

		@@ -750,9 +761,12 @@ func TestMetadataBatcher_TimestampOrdering(t *testing.T) {
		psCap.requireContainsAll([]uuid.UUID{agent})

		// Verify only 1 entry was flushed (newest timestamp wins)

		// intermittently. See "Wait for Full Completion before Asserting" in
		// .claude/docs/TESTING.md.

		@@ -1001,8 +1015,11 @@ func TestMetadataBatcher_ConcurrentAddsToSameAgent(t *testing.T) {
		psCap.requireContainsAll([]uuid.UUID{agentID})

		// Verify exactly 3 unique keys were flushed

		counts := func(t require.TestingT) map[string]float64 {
		metrics, err := registry.Gather()

Conversation

eric-hughes-coder commented Oct 16, 2026

Testing defects

The Original

The Additional

Fixes

Documentation

Uh oh!

linear-code Bot commented Oct 16, 2026

Uh oh!

nickvigilante left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

This branch has not been deployed

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants