Go 1.16: TestRateCounterHighResolution fails

[eclipseo]

On Fedora Rawhide with Go 1.16 beta, the test TestRateCounterHighResolution fails:

Testing    in: /builddir/build/BUILD/ratecounter-a05fe2ccb7bd521822002ddbd47903ac1ed1eb63/_build/src
         PATH: /builddir/build/BUILD/ratecounter-a05fe2ccb7bd521822002ddbd47903ac1ed1eb63/_build/bin:/usr/bin:/bin:/usr/sbin:/sbin:/usr/local/sbin
       GOPATH: /builddir/build/BUILD/ratecounter-a05fe2ccb7bd521822002ddbd47903ac1ed1eb63/_build:/usr/share/gocode
  GO111MODULE: off
      command: go test -buildmode pie -compiler gc -ldflags " -X github.com/paulbellamy/ratecounter/version=0.2.0 -X github.com/paulbellamy/ratecounter/version.commit=a05fe2ccb7bd521822002ddbd47903ac1ed1eb63 -extldflags '-Wl,-z,relro -Wl,--as-needed  -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld  '"
      testing: github.com/paulbellamy/ratecounter
github.com/paulbellamy/ratecounter
--- FAIL: TestRateCounterHighResolution (0.08s)
    ratecounter_test.go:90: Expected  3  to equal  2
    ratecounter_test.go:90: Expected  3  to equal  1
    ratecounter_test.go:90: Expected  3  to equal  0
FAIL
exit status 1
FAIL	github.com/paulbellamy/ratecounter	2.157s

[paulbellamy]

@eclipseo Thanks a bunch for the bug report. This is interesting. 🤔 I don't personally use red hat. Do you want to investigate? Or any hunches on what might be wrong?

[eclipseo]

I'm not well versed in Go enough to find out the cause. Have you tried reproducing with Golang 1.16?

[paulbellamy]

Got it. I have tried nothing yet. I'll try to have a go at it this weekend.

…

On Mon, 1 Feb 2021 at 14:32, Robert-André Mauchin ***@***.***> wrote: I'm not well versed in Go enough to find out the cause. Have you tried reproducing with Golang 1.16? — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#22 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAB5CV4ACRQGE4NRBSR2JY3S423QPANCNFSM4WQYYE4Q> .

[paulbellamy]

Ok, so this is easily reproducible under docker with:

$ docker run --rm -ti -v "$PWD:/app" -w /app golang:1.16rc1 go test ./...
--- FAIL: TestRateCounterHighResolution (0.08s)
    ratecounter_test.go:90: Expected  3  to equal  2
    ratecounter_test.go:90: Expected  3  to equal  1
    ratecounter_test.go:90: Expected  3  to equal  0
FAIL
FAIL    github.com/paulbellamy/ratecounter      2.178s

Tests usually seem to usually run fine on golang 1.15, but different tests occasionally fail when the race detector is enabled:

$ docker run --rm -ti -v "$PWD:/app" -w /app golang:1.15 go test -race ./...
--- FAIL: TestAvgRateCounterAdvanced (0.16s)
    avgratecounter_test.go:40: Expected rate  0  to equal  3
--- FAIL: TestRateCounterNoResolution (0.08s)
    ratecounter_test.go:197: Expected  0  to equal  3
FAIL
FAIL    github.com/paulbellamy/ratecounter      2.204s
FAIL

Interestingly it doesn't always fail, and never finds a data race. Could be a test expectation race. I wonder if 1.16 changed something about the timings that is causing the tests to fail now... 🤔 I don't see anything obvious in https://github.com/golang/go/blob/master/doc/go1.16.html, but maybe this is a nice opportunity to make the tests more robust anyway.

...

After playing around with it for a bit, I'm pretty sure it's a race condition in the test expectations. The "proper" way to fix this is to use a mock clock for testing. But most of the mock clock implementations in go do a poor job simulating the subtler aspects of Tickers, and a lot of them have performance implications. To use a mock ticker we'd need to loosen some of this library's expectations around tickers (a good thing anyway), which would incidentally be a good time to fix #14.

Needs a bit of thought. Thanks raising the issue.