Fix flaky Windows CI tests and a LogThrottleRetryer event-drop bug - #2229
Open
sky333999 wants to merge 3 commits into
Open
Fix flaky Windows CI tests and a LogThrottleRetryer event-drop bug#2229sky333999 wants to merge 3 commits into
sky333999 wants to merge 3 commits into
Conversation
Under load the watcher goroutine can be preempted while ShouldRetry pushes throttle events onto throttleChan. With the original buffer of 1 and a non-blocking send, consecutive events were silently dropped (observed ~6/200 lost under CI contention), and Stop() returned before the watcher drained, so callers could miss the final events. - Enlarge throttleChan buffer 1 -> 1024 (non-blocking send still guarantees the AWS SDK error path never blocks). - Drain throttleChan on shutdown before the watcher returns (Go's randomized select could otherwise strand queued events on the <-done path). - Make Stop() synchronous via a 'stopped' channel so callers observe all events. Also add Debugf logging at tail.OpenFileCount transitions (TailFile/CloseFile/ Reopen) to aid future tailer-lifecycle triage; debug-level only, no behavior change.
Windows' ~15.6ms timer tick under 'make test' CPU contention makes fixed
time.Sleep + one-shot assertion patterns race. Replace them with
assert.Eventually/require.Eventually polling, widen over-tight wall-clock
budgets, use channel synchronization, and make one assertion deterministic:
- TimedDeleterWithIDCheck_DeleteWithDelay_{NoUpdate,WithUpdate,InvalidType}:
Eventually/Never instead of racing a 10ms delay + 20ms sleep.
- TestConvertOtelMetrics_{Dimensions,NoDimensions,Histogram} (checkDatum):
timestamp-recency budget 1s -> 1min (real drift is hours, not seconds).
- TestTailerSrc: drop the racy OpenFileCount==before+1 check (process-global
atomic mutated by sibling tailers); leak detection via the existing Eventually.
- TestMiddleware: wait on channels for each middleware phase instead of a fixed 4s sleep.
- TestBackoffRetries: cache elapsed once and widen upper-bound leniency 200ms -> 500ms.
- TestPublish: poll len(svc.Calls) instead of sleeping a fixed interval + hard assert.
- TestLogsFileRemove: widen post-deletion grace 1s -> 10s.
- TestAdmitAndRollup: feed 10 distinct keys so exactly-2-admitted is deterministic
(random keys could trigger legitimate top-K rotation and admit a 3rd).
- TestExistingAttributesNotOverwritten: poll for the async EC2 tag/metadata/volume
fetches instead of a fixed 1s sleep.
- TestNewFileManagerSink: drain sleep 1ms -> 200ms (1ms is below the Windows tick).
- TestReadGaps: poll for the async state-file flush instead of a fixed 200ms read.
Follow-up to the buffer/drain/sync-Stop fix, from an adversarial review: - Cap throttleChan buffer at 128 (was 1024): holds a full burst with headroom while bounding memory; 1024 was an unjustified magic number. - Guard Stop() with sync.Once so a double call can't panic on close(done). Current callers Stop() once, but the type had no protection for future callers. - Drop the now-vestigial time.Sleep() calls after Stop() in the tests; Stop() is synchronous (drains + waits for the watcher), so the sleeps are dead weight.
Contributor
Binary Size Reportlinux/amd64
linux/arm64
windows/amd64
Investigating size changesUse go-size-analyzer to compare binaries: GOEXPERIMENT=jsonv2 go install github.com/Zxilly/go-size-analyzer/cmd/gsa@latest
gsa diff --old <baseline-binary> --new <new-binary> |
Contributor
|
This PR was marked stale due to lack of activity. |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
Windows CI (
make testonwindows-latest) had an ambient ~7–20% flake rate. Root cause for nearly all of it: Windows' ~15.6 ms timer-tick resolution, under the CPU contention of ~50 package test binaries running in parallel, makestime.Sleep+ one-shot-assertion patterns race their wall-clock deadlines. This PR fixes the flaky tests and one real (minor) production bug surfaced during the investigation.LogThrottleRetryerproduction fix (+tail.godebug logging)Source change
internal/retryer/logthrottle.go— LogThrottleRetryer silently dropped throttle-detected log events.throttleChanhad a buffer of 1 with a non-blocking send, so when the watcher goroutine was preempted, consecutive throttle events were dropped (~6/200 lost under contention);Stop()also returned before the watcher drained, so the final aggregated count could be under-reported.Impact is diagnostic only — the
"AWS API call has been throttled N times"summary could undercount during a throttling storm. No retry/availability impact (the SDK still retries). Note the one-slot buffer was leftover from an earlier blocking implementation; the drop behavior was introduced incidentally by the later non-blocking deadlock fix (#2190). This change restores the original "log every event" intent without reintroducing the deadlock.Fix:
throttleChanbuffer 1 → 128 (holds a burst with headroom, bounded memory; the non-blocking send still guarantees the AWS SDK path never blocks).throttleChanon shutdown before the watcher returns.Stop()synchronous (waits for the watcher to drain and exit), guarded bysync.Onceso a double call can't panic onclose(done).plugins/inputs/logfile/tail/tail.go— addedDebugflogging atOpenFileCounttransitions to aid tailer-lifecycle triage. Debug-level only; no behavior change.Test fixes
TimedDeleterWithIDCheck_DeleteWithDelay_{NoUpdate,WithUpdate,InvalidType}Eventually/Neverinstead of a 10 ms delay + 20 ms sleepTestConvertOtelMetrics_{Dimensions,NoDimensions,Histogram}TestTailerSrcOpenFileCount==before+1check (process-global atomic mutated by sibling tailers)TestMiddlewareTestBackoffRetrieselapsedonce; widen upper-bound leniency 200 ms → 500 msTestPublishlen(svc.Calls)instead of a fixed-interval sleep + hard assertTestLogsFileRemoveTestAdmitAndRollupTestExistingAttributesNotOverwrittenTestNewFileManagerSinkTestReadGapsTestLogThrottleRetryerLogging+ siblingtime.Sleep()afterStop()(Stop is synchronous)Validation
Each fix was validated with an A/B repro harness (30-iteration
make testloops onwindows-latest, cache-busted, baseline vs. fixed legs). Final run: fixed leg 30/30 clean across all 16 targeted tests, 0 unrelated failures; the baseline leg kept reproducing the flakes. All fixes also pass local stress runs (Linux +GOOS=windowsvet/build; 1000× for the deterministic ones; 20× for the retryer package after the review changes).