mvcc: syncWatchersLoop can panic with "non-positive interval for Ticker.Reset" where the monotonic clock is coarse (windows/amd64)
- Dominant language
- Go
- Stars
- 52.3k
- Forks
- 10.5k
- Avg merge
- 3d 1h
- Merged PRs (30d)
- 44
Description
`watchableStore.syncWatchersLoop` measures how long a `syncWatchers` pass took and, when the
pass made progress but watchers are still unsynced, resets its delay ticker to that duration so
the loop yields time to other store operations:
```go
syncDuration := time.Since(st)
delayTicker.Reset(watchResyncPeriod)
// more work pending?
if unsyncedWatchers != 0 && lastUnsyncedWatchers > unsyncedWatchers {
// be fair to other store operations by yielding time taken
delayTicker.Reset(syncDuration)
}
```
`time.Ticker.Reset` panics on a non-positive interval, and `time.Since` can return exactly zero
when the pass finishes faster than the platform's monotonic clock can resolve. The panic happens
in a goroutine started by `mvcc.New`, so it is not recoverable and takes the process down.
On windows/amd64 the Go runtime's monotonic clock has a resolution of roughly 500 microseconds,
so this is not a rare race, it is the common case for a fast sync pass. Measured with a small
program on this machine, 200000 iterations of `st := time.Now(); d := time.Since(st)`:
```
== WINDOWS ==
samples=200000 zero-duration=199998 (100.0%) smallest-nonzero=504.3µs
== LINUX (docker) ==
samples=200000 zero-duration=0 (0.0%) smallest-nonzero=15ns
```
Reproduction, on Windows 11, Go 1.26.6, against `main` at `f744d457`:
```
go test -count=1 -run "TestWatch" ./storage/mvcc/
```
```
panic: non-positive interval for Ticker.Reset
goroutine 330 [running]:
time.(*Ticker).Reset(0x7eec7680070?, 0x5f5e100?)
.../src/time/tick.go:67 +0x69
go.etcd.io/etcd/server/v3/storage/mvcc.(*watchableStore).syncWatchersLoop(0x7eec7350140)
.../server/storage/mvcc/watchable_store.go:246 +0x19f
created by go.etcd.io/etcd/server/v3/storage/mvcc.New in goroutine 376
.../server/storage/mvcc/watchable_store.go:87 +0x85
FAIL go.etcd.io/etcd/server/v3/storage/mvcc 6.366s
```
Reproduced 5 times out of 5. On Linux the same command passes, and the full `server` module unit
suite passes, which is consistent with the clock resolution measurement above.
Why this has not been noticed: there is no Windows runner in `.github/workflows`, and the Prow
presubmits are Linux. `scripts/build-binary.sh` does build and ship `windows` release binaries
(`for os in darwin windows linux`), so the affected code does get distributed.
Contributor guide
Research direction
Start in server/storage/mvcc/watchable_store.go at syncWatchersLoop and inspect the delayTicker.Reset calls around the sync duration measurement. Run go test -count=1 -run "TestWatch" ./storage/mvcc/ on Windows or another coarse-clock environment, then verify the watcher tests complete without a non-positive Ticker.Reset panic.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- go
- Domain
- databases, distributed-systems
- Issue type
- Bug
- Difficulty
- 3/5
- Estimated time
- 1-2 days
- Activity status
- Quiet
- Clarity
- Mostly clear
- Newbie friendliness
- 72/100