Skip to content

runtime,time: Timer.Reset returns true after Stop returned false and no value was received #80760

Description

@h2zi

Go version

go1.26.5 darwin/arm64

Output of go env in your module/workspace:

AR='ar'
CC='cc'
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_ENABLED='1'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
CXX='c++'
GCCGO='gccgo'
GO111MODULE=''
GOARCH='arm64'
GOARM64='v8.0'
GOAUTH='netrc'
GOBIN=''
GOCACHE='/Users/haozi/Library/Caches/go-build'
GOCACHEPROG=''
GODEBUG=''
GOENV='/Users/haozi/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFIPS140='off'
GOFLAGS=''
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/cg/cz4tt4hj2mxbs_brbwkgpxxw0000gn/T/go-build4107655364=/tmp/go-build -gno-record-gcc-switches -fno-common'
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMOD='/tmp/timerrepro/go.mod'
GOMODCACHE='/Users/haozi/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/haozi/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOSUMDB='sum.golang.org'
GOTELEMETRY='local'
GOTELEMETRYDIR='/Users/haozi/Library/Application Support/go/telemetry'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/opt/homebrew/Cellar/go/1.26.5/libexec/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.26.5'
GOWORK=''
PKG_CONFIG='pkg-config'

What did you do?

I keep time.Timers in a sync.Pool (same pattern as fasthttp's AcquireTimer/ReleaseTimer). The owner goroutine waits on t.C in a select that also has another ready case, so the timer expiring can race the select picking the other case. On release I call t.Stop(), and if it returns false I do a non-blocking drain of t.C, then put the timer back. On the next Get I call t.Reset(d) and check the return value.

All calls on a given timer happen one after another (Stop, drain, Put, Get, Reset — the pool provides the ordering, and each worker only touches its own timers).

Reproducer, stdlib only:

// Reproduces time.Timer.Reset reporting an active timer after Stop returned
// false, using a pooled timer racing another select case.
package main

import (
	"fmt"
	"math/rand"
	"os"
	"runtime"
	"sync"
	"time"
)

var timerPool sync.Pool

func acquire(d time.Duration) *time.Timer {
	v := timerPool.Get()
	if v == nil {
		return time.NewTimer(d)
	}
	t := v.(*time.Timer)
	if t.Reset(d) {
		fmt.Println("REPRODUCED: Reset reported an active pooled timer")
		os.Exit(1)
	}
	return t
}

func release(t *time.Timer) {
	if !t.Stop() {
		select {
		case <-t.C:
		default:
		}
	}
	timerPool.Put(t)
}

func main() {
	fmt.Println(runtime.Version(), "GOMAXPROCS", runtime.GOMAXPROCS(0))
	var wg sync.WaitGroup
	for w := range 16 {
		wg.Add(1)
		go func(seed int64) {
			defer wg.Done()
			r := rand.New(rand.NewSource(seed))
			events := make(chan struct{}, 4)
			var peer sync.WaitGroup
			deadline := time.Now().Add(120 * time.Second)
			for time.Now().Before(deadline) {
				d := time.Duration(10+r.Intn(150)) * time.Microsecond
				t := acquire(d)
				peer.Add(1)
				go func(fireAt time.Duration) {
					defer peer.Done()
					time.Sleep(fireAt)
					select {
					case events <- struct{}{}:
					default:
					}
				}(time.Duration(float64(d) * (0.8 + 0.4*r.Float64())))
				// A couple of waits on the same armed timer, racing events.
				for range 1 + r.Intn(2) {
					select {
					case <-t.C:
					case <-events:
					}
				}
				release(t)
				peer.Wait()
				for {
					select {
					case <-events:
						continue
					default:
					}
					break
				}
			}
		}(int64(w))
	}
	wg.Wait()
	fmt.Println("no repro in 120s")
}

What did you see happen?

Usually well within the 120s window it prints:

go1.26.5 GOMAXPROCS 10
REPRODUCED: Reset reported an active pooled timer
exit status 1

So on the same timer, calls in this order:

  1. t.Stop() returned true (so the release path skipped the drain)
  2. nothing was ever received from t.C for this arming
  3. t.Reset(d) returned true

(I originally reported the failing pair as Stop=false + empty drain + Reset=true; instrumenting the reproducer to record Stop's result showed it is actually Stop=true. See the first comment.)

go run -race . also reproduces and reports no races, so I don't think the program itself is racy.

GODEBUG=asynctimerchan=1 go run . does not reproduce (full 120s, several runs), so this looks specific to the synchronous timer channels.

What did you expect to see?

Stop's doc says it returns "true if the call stops the timer". Reset's doc says it returns "true if the timer had been active, false if the timer had expired or been stopped". Stop just reported that it stopped the timer, nothing re-armed it in between, and no value was ever delivered on t.C, so I expected Reset to return false. The two calls disagree about the state of the same idle timer.

This looks related to but different from #69312: that was about Stop's return value and was fixed for 1.23; here the wrong value comes from Reset, on a toolchain that already has that fix. I didn't manage to pin down the exact interleaving in the runtime, but the trigger is the expiry racing the owner's select choosing the other case.

For what it's worth, this is how it was found: fasthttp's initTimer sanity check panics with "BUG: active timer trapped into initTimer()" under HTTP/2 load because of this sequence.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

FixPendingIssues that have a fix which has not yet been reviewed or submitted.NeedsInvestigationSomeone must examine and confirm this is a valid issue and not a duplicate of an existing one.compiler/runtimeIssues related to the Go compiler and/or runtime.

Type

No type

Projects

Relationships

None yet

Development

No branches or pull requests

Issue actions