Skip to content

CI reports phantom test failures due to stdout interleaving with go test -json stream #8385

Description

@vhvb1989

Summary

CI pipelines report phantom test failures — tests that actually pass but appear as failures in gotestsum's summary and in the Azure DevOps "Tests" tab. This makes it impossible to quickly distinguish real failures from noise, undermining CI signal reliability.

Example from build 6353113:

  • Windows job: DONE 13911 tests, 43 skipped, 10 failuresjob green (all 10 are phantom)
  • Linux job: DONE 13935 tests, 31 skipped, 15 failuresjob red (14 phantom + 1 real)
  • The Azure DevOps "Tests" tab shows 10 tests as "failed" on Windows even though the job passed

A developer investigating the Linux failure sees "15 failures" and has to manually inspect each one to find the single real failure (Test_CLI_Up_ResourceGroupScope). The phantom failures are only identifiable by their (unknown) duration marker.

Root Cause Analysis

The mechanism

1. Tests write directly to os.Stdout

Several test paths exercise UX components (ux.Spinner, ux.Select, ux.Input) that default their Writer to os.Stdout. For example, pkg/prompt/prompt_service.go:817-820 creates a spinner without specifying a writer, and most prompt tests don't set SkipLoadingSpinner: true.

2. Stdout output corrupts go test -json's event stream

go test -json works by prepending a marker byte (0x16) to framework lines (--- PASS, === RUN, etc.) so the internal test2json converter can distinguish them from test output. When the spinner writes "| Loading resources..." directly to os.Stdout, it enters the same pipe. Under heavy parallel load, writes interleave at the byte/line level:

| Loading resources...=== CONT  TestDefaultPrompter_PromptLocation_FilterExcludes

(actual line from the CI log — spinner output and framework line fused on one line)

When a --- PASS: TestFoo (0.00s) line gets concatenated after spinner output, test2json can't recognize the marker — the line starts with |, not the marker byte. It treats the --- PASS as plain output and never emits an ActionPass JSON event.

3. gotestsum synthesizes failures for missing end events

When all tests in a package finish, gotestsum's Package.end() (execution.go:285-305) checks for tests that received ActionRun but never received ActionPass/ActionFail/ActionSkip. It synthesizes ActionFail with Elapsed = neverFinished, which renders as "(unknown)" in the summary.

4. Exit code mismatch

  • go test exits 0 because it tracks failures internally via t.Failed(), not through output parsing — all tests actually passed.
  • gotestsum exits 0 because it mirrors go test's exit code, not its own failure count.
  • ci-test.ps1 only checks $LASTEXITCODE0green.

But gotestsum's DONE summary and its JUnit XML report (published to Azure DevOps) both include the phantom failures, so the "Tests" tab shows them as failed.

How to distinguish phantom vs real failures

Phantom failure Real failure
Duration (unknown) Actual duration, e.g. (122.31s)
Error output None — only the === FAIL summary line Has Error Trace:, assertion messages
--- PASS present Yes, appears nearby in the raw log No
go test exit code 0 1

Evidence from build 6353113

Windows (all phantom):

=== Failed
=== FAIL: pkg/prompt TestPromptCustomResource_LoadDataError (unknown)

--- PASS: TestPromptCustomResource_LoadDataError (0.00s)

DONE 13911 tests, 43 skipped, 10 failures in 5864.869s

Linux (14 phantom + 1 real):

=== FAIL: pkg/prompt TestPromptCustomResource_NilSelectorOptions_UsesDefaultsAndForce (unknown)   ← phantom
=== FAIL: test/functional Test_CLI_Up_ResourceGroupScope (122.31s)                                ← real
    Error Trace: up_test.go:515
    Error:       Received unexpected error:
                 command 'azd provision' had non-zero exit code: exit status 1

Affected tests

Consistently affected (appear as phantom failures in CI)

pkg/prompt — 7-9 tests per run (use t.Parallel(), exercise spinner via PromptCustomResource):

  • TestPromptService_PromptSubscriptionResource_NoPrompt_FallbackName
  • TestPromptService_PromptSubscriptionResource_NoPrompt_CustomDisplayName
  • TestPromptService_PromptSubscriptionResource_NoPrompt_Errors
  • TestPromptService_PromptResourceGroupResource_NoPrompt_CustomDisplayName
  • TestPromptService_PromptResourceGroupResource_NoPrompt_FallbackName
  • TestPromptService_PromptResourceGroupResource_NoPrompt_Errors
  • TestPromptCustomResource_NoResourcesAndNotAllowedNew_ReturnsSentinel
  • TestPromptCustomResource_LoadDataError
  • TestDefaultPrompter_PromptLocation_FilterExcludes
  • TestDefaultPrompter_PromptLocation_HappyPath

pkg/ux/internal — 3 tests per run (hardcoded os.Stdout in input.go):

  • TestReadInput_NonNilConfig
  • TestReadInput_ContextCancellationReturnsErrCancelled
  • TestReadInput_SetTermModeErrorOnNonTTY

Proposed fix plan

Fix classification

Category Description Test count Fix approach
A Test creates UX component directly with default os.Stdout ~20 tests Inject io.Discard or &bytes.Buffer{} as Writer in test setup
B Test calls production code that internally creates UX component with default os.Stdout ~10 tests Use existing SkipLoadingSpinner: true option, or add Writer parameter to production code paths
C Test uses fmt.Print* directly ~7 tests Convert to t.Log*
D Logger defaulting to stdout 0 N/A

Category A — Direct UX component construction in tests (~20 tests)

Tests that create ux.NewSpinner, ux.NewSelect, or internal.NewInput without setting Writer:

  • pkg/ux/render_test.go — 8 tests (TestNewSpinner_*, TestSpinner_*)
  • pkg/ux/select_test.go — 8 tests (TestNewSelect_*, TestSelect_Render_*)
  • pkg/ux/internal/input_test.go — 4 tests (TestNewInput, TestReadInput_*)

Fix: Set Writer: io.Discard (or &bytes.Buffer{} when output is asserted) in test options.

Category B — Production code creates UX with default stdout (~10 tests)

Tests that call PromptCustomResource, PromptSubscriptionResource, AskerConsole etc. which internally create spinners/selects with default os.Stdout:

  • pkg/prompt/prompt_service_extra_test.go — 5 tests
  • pkg/prompt/prompter_extra_test.go — 2 tests
  • pkg/input/console_test.go — 4 tests

Fix: Use SkipLoadingSpinner: true where applicable. For paths where spinner behavior must be tested, thread a Writer option through the production code (e.g., add Writer to ResourceSelectorOptions).

Category C — Direct fmt.Print* in tests (~7 tests)

  • test/functional/experiment_test.go — 1 test
  • test/functional/telemetry_test.go — 1 test
  • pkg/azdext/testing_helpers_test.go — 5 tests (these intentionally test stdout capture, may need special handling)

Fix: Convert fmt.Printf to t.Logf. For testing_helpers_test.go, these tests are specifically testing stdout capture — they may need a //nolint annotation.

Prevention — Lint rule

To prevent regressions, add a forbidigo rule to .golangci.yaml that forbids fmt.Print* and os.Stdout in test files:

linters:
  enable:
    - forbidigo

linters-settings:
  forbidigo:
    forbid:
      - p: ^fmt\.Print.*$
        msg: "Use t.Log/t.Logf in tests instead of fmt.Print to avoid corrupting go test -json output"
      - p: ^os\.Stdout$
        msg: "Do not use os.Stdout in tests; inject io.Discard or a bytes.Buffer to avoid corrupting go test -json output"
    analyze-types: true

A custom go/analysis analyzer could provide more precise detection (e.g., catching NewSpinner calls without Writer set), but forbidigo covers the most common patterns and is already supported by golangci-lint.

Impact

  • Eliminates ~10-14 phantom failures per CI run across all platforms
  • Makes the Azure DevOps "Tests" tab accurate — green means all tests passed
  • Makes the DONE summary line trustworthy for quick failure triage
  • Prevents future regressions via lint rule

Metadata

Metadata

Assignees

Labels

area/pipelineCI/CD pipeline config (GH Actions, AzDO)bugSomething isn't workingtest automationTest infrastructure work

Type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions