ci: Run unit tests with -race

[dnephin]

I've attempted to enable 'go test -race', but there are many failures (example). Data races could cause flaky tests, and may even cause issues in production.

I'm starting work on this in #8269. This issue is to track packages that have failures so that we can fix them incrementally.

• agent/cache-types - ci: change go-test-race package list to exclude list #9160
• agent/local
• agent/xds - xds: enable race detector and some small cleanup #9461
• connect - ci: change go-test-race package list to exclude list #9160
• connect/proxy - ci: change go-test-race package list to exclude list #9160
• agent
• agent/consul - WIP: fix remaining data races #10341
• snapshot
• command/{acl,etc...} - WIP: fix remaining data races #10341
• (other packages not yet listed)

Related issues:

• Data Races memberlist#134 (comment) looks to still be an issue
• Data Race in buildServerState raft-autopilot#3
• data race in lib/serf.UpdateTag #9457
• race: handleNodeLeaveIntent reads state field without acquiring state lock serf#622
• data race: TestLeader_Vault_PrimaryCA_IntermediateRenew modifies a global without a lock #9458

[dnephin]

I'm seeing some of the TestCheck* tests in agent/checks fail on master due to races (https://circleci.com/gh/hashicorp/consul/209863, https://circleci.com/gh/hashicorp/consul/209838).

Some of the stacks are missing (I think that is due to another bug in Go that I patched and will be in go1.15). I tried to reproduce locally and it appears to be a race with t.Log and the test shutting down. I guess the goroutines outlive the test, so maybe the root cause is a leaked go routine.

I think #7948 may fix the immediate problem with the race.

stack traces

WARNING: DATA RACE
Read at 0x00c000496b83 by goroutine 28:
  testing.(*common).logDepth()
      /usr/lib/go/src/testing/testing.go:675 +0x14b
  testing.(*common).log()
      /usr/lib/go/src/testing/testing.go:662 +0x77
  testing.(*common).Log()
      /usr/lib/go/src/testing/testing.go:694 +0x1d
  testing.(*T).Log()
      <autogenerated>:1 +0x61
  github.com/hashicorp/consul/sdk/testutil.(*testWriter).Write()
      /home/daniel/pers/code/consul/sdk/testutil/testlog.go:86 +0x319
  github.com/hashicorp/go-hclog.(*writer).Flush()
      /home/daniel/go/pkg/mod/github.com/hashicorp/go-hclog@v0.12.0/writer.go:29 +0x28c
  github.com/hashicorp/go-hclog.(*intLogger).log()
      /home/daniel/go/pkg/mod/github.com/hashicorp/go-hclog@v0.12.0/intlogger.go:140 +0x20c
  github.com/hashicorp/go-hclog.(*intLogger).Debug()
      /home/daniel/go/pkg/mod/github.com/hashicorp/go-hclog@v0.12.0/intlogger.go:442 +0x9f
  github.com/hashicorp/go-hclog.(*interceptLogger).Debug()
      /home/daniel/go/pkg/mod/github.com/hashicorp/go-hclog@v0.12.0/interceptlogger.go:62 +0xaf
  github.com/hashicorp/consul/agent/checks.(*StatusHandler).updateCheck()
      /home/daniel/pers/code/consul/agent/checks/check.go:828 +0x2d6
  github.com/hashicorp/consul/agent/checks.(*CheckHTTP).check()
      /home/daniel/pers/code/consul/agent/checks/check.go:489 +0x88b
  github.com/hashicorp/consul/agent/checks.(*CheckHTTP).run()
      /home/daniel/pers/code/consul/agent/checks/check.go:423 +0xac

Previous write at 0x00c000496b83 by goroutine 18:
  testing.tRunner.func1()
      /usr/lib/go/src/testing/testing.go:977 +0x467
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:995 +0x20d

Goroutine 28 (running) created at:
  github.com/hashicorp/consul/agent/checks.(*CheckHTTP).Start()
      /home/daniel/pers/code/consul/agent/checks/check.go:402 +0x170
  github.com/hashicorp/consul/agent/checks.TestCheckHTTPBody.func2()
      /home/daniel/pers/code/consul/agent/checks/check_test.go:639 +0x700
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:991 +0x1eb

Goroutine 18 (running) created at:
  testing.(*T).Run()
      /usr/lib/go/src/testing/testing.go:1042 +0x660
  testing.runTests.func1()
      /usr/lib/go/src/testing/testing.go:1284 +0xa6
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:991 +0x1eb
  testing.runTests()
      /usr/lib/go/src/testing/testing.go:1282 +0x527
  testing.(*M).Run()
      /usr/lib/go/src/testing/testing.go:1199 +0x2ff
  github.com/hashicorp/consul/agent/checks.TestMain()
      /home/daniel/pers/code/consul/agent/checks/grpc_test.go:71 +0x5f8
  main.main()
      _testmain.go:112 +0x223

[dnephin]

agent/router TestMain appears to be failing sometimes. CI missing the output (maybe another test2json bug?), but I was able to reproduce locally:

stack traces

==================
WARNING: DATA RACE
Read at 0x00c0000fb003 by goroutine 134:
  testing.(*common).logDepth()
      /usr/lib/go/src/testing/testing.go:669 +0xa1
  testing.(*common).log()
      /usr/lib/go/src/testing/testing.go:662 +0x77
  testing.(*common).Log()
      /usr/lib/go/src/testing/testing.go:694 +0x1d
  testing.(*T).Log()
      <autogenerated>:1 +0x61
  github.com/hashicorp/consul/sdk/testutil.(*testWriter).Write()
      /home/daniel/pers/code/consul/sdk/testutil/testlog.go:86 +0x319
  github.com/hashicorp/go-hclog.(*writer).Flush()
      /home/daniel/go/pkg/mod/github.com/hashicorp/go-hclog@v0.12.0/writer.go:29 +0x28c
  github.com/hashicorp/go-hclog.(*intLogger).log()
      /home/daniel/go/pkg/mod/github.com/hashicorp/go-hclog@v0.12.0/intlogger.go:140 +0x20c
  github.com/hashicorp/go-hclog.(*intLogger).Info()
      /home/daniel/go/pkg/mod/github.com/hashicorp/go-hclog@v0.12.0/intlogger.go:452 +0x9f
  github.com/hashicorp/go-hclog.(*interceptLogger).Info()
      /home/daniel/go/pkg/mod/github.com/hashicorp/go-hclog@v0.12.0/interceptlogger.go:76 +0xaf
  github.com/hashicorp/consul/agent/router.(*Manager).Start()
      /home/daniel/pers/code/consul/agent/router/manager.go:526 +0x1bc

Previous write at 0x00c0000fb003 by goroutine 22:
  testing.tRunner.func1()
      /usr/lib/go/src/testing/testing.go:977 +0x467
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:995 +0x20d

Goroutine 134 (running) created at:
  github.com/hashicorp/consul/agent/router.(*Router).addServer()
      /home/daniel/pers/code/consul/agent/router/router.go:252 +0x613
  github.com/hashicorp/consul/agent/router.(*Router).AddArea()
      /home/daniel/pers/code/consul/agent/router/router.go:161 +0x66c
  github.com/hashicorp/consul/agent/router.TestRouter_Routing()
      /home/daniel/pers/code/consul/agent/router/router_test.go:172 +0x52e
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:991 +0x1eb

Goroutine 22 (running) created at:
  testing.(*T).Run()
      /usr/lib/go/src/testing/testing.go:1042 +0x660
  testing.runTests.func1()
      /usr/lib/go/src/testing/testing.go:1284 +0xa6
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:991 +0x1eb
  testing.runTests()
      /usr/lib/go/src/testing/testing.go:1282 +0x527
  testing.(*M).Run()
      /usr/lib/go/src/testing/testing.go:1199 +0x2ff
  main.main()
      _testmain.go:88 +0x223
==================

[pierresouchay]

checks is failing a lot as well it seems, on my machine, on 2nd/3rd run, this fails on master branch:

date; i=0;while go test -p 2 -race -gcflags=all=-d=checkptr=0 -timeout 60s github.com/hashicorp/consul/agent/checks; do go clean -testcache; i=$((i + 1)); done; echo failed at $i; date

[dnephin]

That last PR (#8346) should have fixed checks for HTTP and Alias. Are you seeing the other ones fail as well? I commented in that PR description that I think the problem exists in all the Check types, but I hadn't seen the rest fail yet, so I wanted to get a quick fix merged to get things green.

I've been using go test -race -count=50 to reproduce the flakes, which also seems to work

[pierresouchay]

indeed with the last patch I cannot reproduce anymore