🐛 fix: de-flake the clock-sensitive tests by ReneWerner87 · Pull Request #4575 · gofiber/fiber

ReneWerner87 · 2026-07-30T13:03:22Z

Description

main has been going red on isolated test failures for months, and the retry that
should absorb them was never running. This fixes both.

Cause 1, the cached clock. The memory storages compare entry expiry against
utils.Timestamp(), a Unix second refreshed by a background 1s ticker, not against the
wall clock. Under -race on a loaded runner that goroutine's store lands up to 1.6s late,
and >100ms late on about half the ticks, so expiry can lag its nominal TTL by roughly two
seconds. Every test that slept TTL + 100..500ms and then asserted expiry was flaky by
construction.

Reproduced at the storage level in 2 of 24 rounds (TTL=5s, 5.1s sleep), and at test level
as the exact failures seen on main in 2 of 8 rounds under GOMAXPROCS=2 with in-process
CPU load. Zero of 8 with the fix. Note the load has to be in-process, an external load
generator does not starve Go's own scheduler and shows nothing.

Cause 2, dead reruns. test.yml sets rerun-fails: '2', but every run aborted with
rerun aborted because previous run had a suspected panic and some test may not have run.
gotestsum flags a package as panicked the moment any output line starts with panic:
(testjson/execution.go addOutput) and cmd/rerunfails.go skips the rerun if any
package is flagged. The recover middleware wrote exactly that prefix for a panic it had
just recovered, so one line cost the whole 4248-test suite its retries.

Affected runs: 30523196027,
30397573119,
28373765289,
28302993228,
28206382069.

Changes introduced

test(session,csrf,limiter) Add internal/clocktest.SleepPast, which sleeps the TTL
and then waits for the cached clock to catch up, and use it where that clock is what
decides. Sleeping longer is not a fix, the updater delay has no upper bound.

I checked per call site which clock actually governs, because the helper shortens the
wall-clock margin and that is only safe where the cached clock decides:

path	clock
session idle timeout (`Save` to `Storage.Set(.., idleTimeout)`)	cached
session absolute timeout (`absExpiration`)	real `time.Now()`
csrf without `Session` (`storageManager`, `internal/memory`)	cached
csrf with `Session` (`token.Expiration.Before(time.Now())`)	real `time.Now()`
limiter windows (`cfg.currentSecond()`)	cached, no `time.Now()` at all

The two real-clock paths are deliberately left on a plain time.Sleep.

test(cache) Test_CacheMaxStaleRespectsProxyRevalidateSharedAuth failed with
expected miss, actual unreachable. A different mechanism: the store phase reads
cfg.now() twice (cache.go:714 and cache.go:784) and charges the whole second in
between as the response's apparent age, which consumes a one-second lifetime entirely.
Raising it to two seconds makes the test immune without changing what it asserts.

test(timeout) TestTimeout_Exceeded bounded elapsed at 150ms against a 50ms timeout
and a 200ms handler sleep, and failed at 150.78ms. Only 100ms of headroom meant it
measured runner load, not early return. Handler sleep to 2s, bound at half of it.

fix(recover) Prefix the default stack trace with recovered, and pin it with a test
that captures the output through an os.Pipe and asserts it no longer looks fatal.

Open question for maintainers

The cache double clock read is a real bug, not just a test annoyance, and I did not touch
it here. A response with max-age=1 fails to be cached at all whenever the store phase
crosses a second boundary, because responseTS - e.date charges fiber's own processing
latency as response age. RFC 9111 defines apparent age against the same response event,
so measuring it from a later clock read manufactures age out of nothing.

Deterministic reproduction through the injectable clock: a request makes three cfg.now()
calls, and moving the boundary to just after the second one turns a max-age=1 store into
unreachable every time.

Fixing it is about two lines (measure the age against nowUnix, keep responseTS as the
expiry anchor) and would remove the same latent exposure from
Test_CacheOnlyIfCachedStaleNotServed, Test_CacheMaxStaleRespectsMustRevalidate and
Test_CacheStaleResponseAddsWarning110, which all assert a cache miss on a max-age=1
store. It also lets the workaround in this PR be reverted. I left it out because it
changes RFC-adjacent freshness math and deserves its own change with its own regression
test. Happy to open that separately.

Type of change

Code consistency (non-breaking change which improves code reliability and robustness)

Note for the release notes: recover's default StackTraceHandler now writes
recovered panic: ... instead of panic: ... to stderr. Not an API change and the
format was never documented, but anyone grepping their logs for that prefix will notice.
EnableStackTrace defaults to false, so most users never see the line at all.

Checklist

Conducted a self-review of the code and provided comments for complex or critical parts.
Added or updated unit tests to validate the effectiveness of the changes or new features.
Ensured that new and existing unit tests pass locally with the changes.
Verified that any new dependencies are essential and have been agreed upon by the maintainers/community. (none added)
Updated the documentation in the /docs/ directory. Not needed, docs/middleware/recover.md documents EnableStackTrace and StackTraceHandler but not the output format.
Benchmarks. Not applicable, no hot-path code changed.

Verification

Full suite -race -count=1 -shuffle=on green, gofmt and go vet clean.
A/B under the reproducing harness (GOMAXPROCS=2, in-process load, -race -count=8):
3 failures before, 0 after. recover package 20x -race -shuffle=on.
gotestsum v1.13.0 with a deliberately failing test: before rerun aborted, after
re-run 1 and re-run 2 both ran, DONE 3 runs over the full suite.
grep -c '^panic: ' over the whole suite output is now 0.

One honest gap: Test_CSRF_ExpiredToken held 8 of 8 in the before state under the same
harness that reliably broke the session tests, so I could not reproduce that one locally.
Its 250ms margin makes it a rarer variant of the same class. The evidence there is the
code path (internal/memory, cached clock) plus the CI signature from run 28206382069
(expected 403, actual 200, token not expired).

The limiter failures that harness produces (app.Test timeouts on tests with 200-300ms
Expiration) are pre-existing. They reproduce identically without this change, none sit
at a sleepForRetryAfter call site, and none appear in CI history.

🤖 Generated with Claude Code

The memory storages compare entry expiry against utils.Timestamp(), a Unix second refreshed by a background 1s ticker, not against the wall clock. Under -race on a loaded runner that goroutine's store lands up to 1.6s late and is >100ms late on about half the ticks, so expiry can lag its nominal TTL by roughly two seconds. Tests that slept TTL plus 100-500ms and then asserted expiry were therefore flaky by construction. Reproduced at the storage level in 2 of 24 rounds with TTL=5s and a 5.1s sleep, and at test level as the exact main failures (session_test.go "Expected nil, but got: john" and Test_Session_WithConfig) in 2 of 8 rounds under GOMAXPROCS=2 with in-process load. Zero of 8 after. Add internal/clocktest.SleepPast, which sleeps the TTL and then waits for that cached clock to catch up, and use it where the cached clock is what decides: session idle timeout, csrf without a Session store, and limiter windows (which read cfg.currentSecond() and never time.Now()). Sleeping longer is not a fix, the updater delay has no upper bound. Left alone on purpose: the session absolute timeout and csrf with a Session store both expire against a real time.Now(), so a wall-clock sleep is correct there. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

Test_CacheMaxStaleRespectsProxyRevalidateSharedAuth failed on main with expected "miss", actual "unreachable". Not the sleep: the store phase reads cfg.now() twice (cache.go:714 for nowUnix, cache.go:784 for ts) and charges the whole second in between as the response's apparent age. With s-maxage=1 that consumes the entire lifetime, so remainingExpiration hits zero and a brand new response is reported unreachable instead of being cached. Reproduced deterministically through the injectable clock: a request makes three cfg.now() calls, and moving the boundary to just after the second one turns a max-age=1 store into "unreachable" every time. Raising the lifetime to two seconds means a stolen second can no longer consume it, and the assertions are unchanged: after 2.5s the entry is stale either way, max-stale=30 would allow it, and proxy-revalidate still forces the revalidation this test is about. This is a workaround for the double clock read, not a fix for it. The same latent exposure remains in Test_CacheOnlyIfCachedStaleNotServed, Test_CacheMaxStaleRespectsMustRevalidate and Test_CacheStaleResponseAddsWarning110, which all assert a cache miss on a max-age=1 store. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

…ner load TestTimeout_Exceeded asserted elapsed < 150ms against a 50ms timeout and a 200ms handler sleep, and failed on main at 150.78ms. With only 100ms between the bound and the handler's own sleep, the assertion tracked how busy the runner was rather than whether the handler returned on cancelation. Raise the handler sleep to 2s and bound at half of it. That keeps what the test is for, a return well before the handler's own timer, with twenty times the timeout as slack, and costs nothing when it passes because the handler still returns after about 50ms. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

defaultStackTraceHandler wrote "panic: %v" to stderr for a panic it had just recovered, a line byte-identical to the runtime's fatal banner. Besides being misleading in any log, it silently disabled the Test workflow's rerun-fails. gotestsum flags a package the moment any output line starts with "panic: " (testjson/execution.go addOutput), and cmd/rerunfails.go aborts the rerun when any package is flagged: ERROR rerun aborted because previous run had a suspected panic and some test may not have run So this single line, reached only through EnableStackTrace with no custom handler, cost the whole 4248-test suite its retries, and every flake on main went red despite rerun-fails being set to 2. Because the write goes straight to os.Stderr it also got misattributed to unrelated tests (golang/go#45508, the issue gotestsum's mitigation cites). Prefix the line with "recovered" and pin it with a test that captures the handler's output through an os.Pipe and asserts it no longer looks fatal, so this cannot regress unnoticed again. Verified with gotestsum v1.13.0 and a deliberately failing test: before, the rerun aborted; after, re-run 1 and re-run 2 both ran over the full suite. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

coderabbitai · 2026-07-30T13:03:40Z

No actionable comments were generated in the recent review. 🎉

ℹ️ Recent review info

⚙️ Run configuration

Configuration used: Repository UI

Review profile: CHILL

Plan: Pro Plus

Run ID: c7690af3-c3e6-44f8-bc14-c17dd47d3b58

📥 Commits

Reviewing files that changed from the base of the PR and between f6c2ac5 and a80c3f6.

📒 Files selected for processing (6)

internal/clocktest/clocktest.go
middleware/csrf/csrf_test.go
middleware/limiter/limiter_test.go
middleware/recover/recover_test.go
middleware/session/middleware_test.go
middleware/session/session_test.go

Walkthrough

Adds a cached-clock test helper and applies it to middleware expiry and retry tests. Cache timing assertions are adjusted, recovered panic output gains a non-fatal prefix with coverage, and timeout tests derive bounds from a named duration.

Changes

Middleware test reliability

Layer / File(s)	Summary
Clock helper and middleware expiry tests `internal/clocktest/clocktest.go`, `middleware/csrf/csrf_test.go`, `middleware/limiter/limiter_test.go`, `middleware/session/*_test.go`	Adds `SleepPast` and replaces wall-clock waits in cached-clock expiration and retry tests.
Cache freshness timing `middleware/cache/cache_test.go`	Updates `s-maxage` and wait durations to match the test’s store-phase timing behavior.
Recovered panic formatting and coverage `middleware/recover/recover.go`, `middleware/recover/recover_test.go`	Changes the output prefix to `recovered panic:` and verifies captured stderr contains stack information without a fatal `panic:` prefix.
Dynamic timeout bound `middleware/timeout/timeout_test.go`	Introduces `handlerSleep` and derives the elapsed-time assertion from that duration.

Estimated code review effort: 3 (Moderate) | ~20 minutes

Suggested reviewers: efectn

Poem

I hop through clocks with a silver key,
Making expired tokens easy to see.
Panic words soften, stacks stand tall,
Cache winds settle, time tests call.
Squeak goes the timer—steady and bright! 🐇

🚥 Pre-merge checks | ✅ 5

✅ Passed checks (5 passed)

Check name	Status	Explanation
Title check	✅ Passed	The title is concise and accurately summarizes the main change: de-flaking clock-sensitive tests.
Description check	✅ Passed	The description covers the problem, changes, type of change, checklist, and verification, with only the issue reference left implicit.
Docstring Coverage	✅ Passed	No functions found in the changed files to evaluate docstring coverage. Skipping docstring coverage check.
Linked Issues check	✅ Passed	Check skipped because no linked issues were found for this pull request.
Out of Scope Changes check	✅ Passed	Check skipped because no linked issues were found for this pull request.

✨ Finishing Touches

📝 Generate docstrings

Create stacked PR
Commit on current branch

🧪 Generate unit tests (beta)

Create PR with unit tests
Commit unit tests in branch fix/flaky-clock-tests-and-test-reruns

Warning

There were issues while running some tools. Please review the errors and either fix the tool's configuration or disable the tool if it's a critical failure.

🔧 golangci-lint (2.12.2)

level=error msg="[linters_context] typechecking error: pattern ./...: directory prefix . does not contain main module or its selected dependencies"

Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

_{Comment @coderabbitai help to get the list of available commands.}

codecov · 2026-07-30T13:06:02Z

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 93.31%. Comparing base (31d7210) to head (a80c3f6).
⚠️ Report is 15 commits behind head on main.

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #4575      +/-   ##
==========================================
+ Coverage   93.25%   93.31%   +0.05%     
==========================================
  Files         140      140              
  Lines       14856    14858       +2     
==========================================
+ Hits        13854    13864      +10     
+ Misses        625      619       -6     
+ Partials      377      375       -2

Flag	Coverage Δ
unittests	`93.31% <100.00%> (+0.05%)`	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Harness.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:

❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

Copilot

Pull request overview

Reduces CI flakiness in clock-sensitive tests by introducing a helper that waits on Fiber’s cached second clock (utils.Timestamp-based expiry), and restores GitHub Actions gotestsum reruns by ensuring the recover middleware’s stack trace output no longer looks like an unrecovered panic.

Changes:

Add internal/clocktest.SleepPast and use it in session/CSRF/limiter tests that are governed by the cached second clock.
Make recover’s default stack trace output start with recovered panic: and add a regression test to prevent gotestsum rerun suppression.
Increase timing headroom in timeout and cache tests to avoid runner-load-driven flakes.

Reviewed changes

Copilot reviewed 9 out of 9 changed files in this pull request and generated 2 comments.

Show a summary per file

File	Description
middleware/timeout/timeout_test.go	Widens timing bounds so the test measures early-cancel behavior rather than runner load.
middleware/session/session_test.go	Replaces wall-clock sleeps with cached-clock-aware waits for idle-timeout expiry checks.
middleware/session/middleware_test.go	Uses cached-clock-aware waits for session idle-timeout behavior.
middleware/recover/recover.go	Changes default stack trace prefix to avoid gotestsum misclassifying recovered panics as crashes.
middleware/recover/recover_test.go	Adds a test that captures stderr and asserts the new non-fatal prefix.
middleware/limiter/limiter_test.go	Uses cached-clock-aware waiting when sleeping past Retry-After windows.
middleware/csrf/csrf_test.go	Uses cached-clock-aware waits for token expiry in non-session CSRF mode; clarifies session-backed expiry uses real clock.
middleware/cache/cache_test.go	Increases s-maxage/sleep to avoid a known second-boundary issue in cached apparent-age math during store.
internal/clocktest/clocktest.go	Introduces the cached-clock-aware wait helper used by the updated tests.

coderabbitai

Actionable comments posted: 1

🧹 Nitpick comments (1)

internal/clocktest/clocktest.go (1)
18-24: 🎯 Functional Correctness | 🔵 Trivial | ⚡ Quick win

Guard or widen the TTL before waiting for the cached timestamp.

uint32(ttl.Seconds()) floors under one second, so sub-second TTLs make want == from and the loop exits immediately. Values >= uint32 seconds overflow to 0. Document a positive whole-second contract and use a wider/correct conversion for the target when durations above one second are supported.
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

In `@internal/clocktest/clocktest.go` around lines 18 - 24, Update SleepPast to
handle TTL conversion safely: enforce or document a positive whole-second TTL
contract, and prevent uint32(ttl.Seconds()) from flooring sub-second values or
overflowing for large durations. If durations above one second remain supported,
compute the target timestamp with a wider or otherwise correct conversion before
waiting.
Source: Linters/SAST tools

🤖 Prompt for all review comments with AI agents

Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

Inline comments:
In `@internal/clocktest/clocktest.go`:
- Around line 25-29: Update SleepPast in the clocktest helper so reaching its
deadline is observable instead of returning silently; after the wait loop,
detect that utils.Timestamp() is still below want and fail the test or return a
status that every caller asserts. Preserve the existing successful path once the
cached clock reaches the target.

---

Nitpick comments:
In `@internal/clocktest/clocktest.go`:
- Around line 18-24: Update SleepPast to handle TTL conversion safely: enforce
or document a positive whole-second TTL contract, and prevent
uint32(ttl.Seconds()) from flooring sub-second values or overflowing for large
durations. If durations above one second remain supported, compute the target
timestamp with a wider or otherwise correct conversion before waiting.

🪄 Autofix (Beta)

Fix all unresolved CodeRabbit comments on this PR:

Push a commit to this branch (recommended)
Create a new PR with the fixes

ℹ️ Review info

⚙️ Run configuration

Configuration used: Repository UI

Review profile: CHILL

Plan: Pro Plus

Run ID: d2a12f2e-1d4b-4637-97d3-ed1a4f7592e0

📥 Commits

Reviewing files that changed from the base of the PR and between 1104ec3 and f6c2ac5.

📒 Files selected for processing (9)

internal/clocktest/clocktest.go
middleware/cache/cache_test.go
middleware/csrf/csrf_test.go
middleware/limiter/limiter_test.go
middleware/recover/recover.go
middleware/recover/recover_test.go
middleware/session/middleware_test.go
middleware/session/session_test.go
middleware/timeout/timeout_test.go

SleepPast returned silently once its 10s deadline passed, so a stuck timestamp updater surfaced as a confusing "entry not expired" assertion in the caller. It now takes a testing.TB and fails there, and the doc comment says that the wait is truncated to the whole seconds the storages compare against. Restore the swapped os.Stderr in the recover test via defer as well, so an unexpected panic in the handler cannot leak the redirect into the rest of the package.

ReneWerner87 and others added 4 commits July 30, 2026 14:54

Copilot AI review requested due to automatic review settings July 30, 2026 13:03

ReneWerner87 requested a review from a team as a code owner July 30, 2026 13:03

ReneWerner87 requested review from efectn, gaby and sixcolors July 30, 2026 13:03

ReneWerner87 added v3 ☢️ Bug labels Jul 30, 2026

Copilot started reviewing on behalf of ReneWerner87 July 30, 2026 13:04 View session

ReneWerner87 added this to v3 Jul 30, 2026

ReneWerner87 added this to the v3 milestone Jul 30, 2026

Copilot AI reviewed Jul 30, 2026

View reviewed changes

Comment thread internal/clocktest/clocktest.go

Comment thread middleware/recover/recover_test.go

coderabbitai Bot reviewed Jul 30, 2026

View reviewed changes

Comment thread internal/clocktest/clocktest.go

gaby changed the title ~~fix: de-flake the clock-sensitive tests on main and restore gotestsum reruns~~ 🐛 fix: de-flake the clock-sensitive tests Jul 30, 2026

ReneWerner87 self-assigned this Jul 30, 2026

ReneWerner87 mentioned this pull request Jul 30, 2026

🐛 bug: stop the cache from charging its own latency as response age #4578

Merged

2 tasks

ReneWerner87 merged commit 9904597 into main Jul 30, 2026
29 checks passed

ReneWerner87 deleted the fix/flaky-clock-tests-and-test-reruns branch July 30, 2026 13:59

github-project-automation Bot moved this to Done in v3 Jul 30, 2026

ReneWerner87 modified the milestones: v3, v3.5.0 Aug 13, 2026

Navigation Menu

Uh oh!

🐛 fix: de-flake the clock-sensitive tests - #4575

🐛 fix: de-flake the clock-sensitive tests#4575
ReneWerner87 merged 5 commits into
mainfrom
fix/flaky-clock-tests-and-test-reruns

ReneWerner87 commented Jul 30, 2026

Uh oh!

coderabbitai Bot commented Jul 30, 2026 •

edited

Loading

Uh oh!

codecov Bot commented Jul 30, 2026 •

edited

Loading

Uh oh!

Copilot AI left a comment

Uh oh!

Uh oh!

Uh oh!

coderabbitai Bot left a comment

Uh oh!

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Uh oh!

Conversation

ReneWerner87 commented Jul 30, 2026

Description

Changes introduced

Open question for maintainers

Type of change

Checklist

Verification

Uh oh!

coderabbitai Bot commented Jul 30, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Walkthrough

Changes

Uh oh!

codecov Bot commented Jul 30, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull request overview

Reviewed changes

Uh oh!

Uh oh!

Uh oh!

coderabbitai Bot left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

coderabbitai Bot commented Jul 30, 2026 •

edited

Loading

codecov Bot commented Jul 30, 2026 •

edited

Loading