Fix beacon-chain/sync Test Race #390

fgimenez · 2018-08-08T15:49:11Z

Towards #377

Running the tests with --features=race I was getting:

WARNING: DATA RACE
Write at 0x00c42011d5a8 by goroutine 35:
  github.com/prysmaticlabs/prysm/beacon-chain/sync.TestSavingBlocksInSync()
      beacon-chain/sync/service_test.go:832 +0xb45
  testing.tRunner()
      GOROOT/src/testing/testing.go:777 +0x16d

Previous read at 0x00c42011d5a8 by goroutine 36:
  github.com/prysmaticlabs/prysm/beacon-chain/sync.(*Service).initialSync()
      bazel-out/k8-fastbuild/bin/proto/beacon/p2p/v1/linux_amd64_race_stripped/v1_go_proto~/github.com/prysmaticlabs/prysm/proto/beacon/p2p/v1/messages.pb.go:223 +0x946
  github.com/prysmaticlabs/prysm/beacon-chain/sync.TestSavingBlocksInSync.func1()
      beacon-chain/sync/service_test.go:759 +0x74

Goroutine 35 (running) created at:
  testing.(*T).Run()
      GOROOT/src/testing/testing.go:824 +0x564
  testing.runTests.func1()
      GOROOT/src/testing/testing.go:1063 +0xa4
  testing.tRunner()
      GOROOT/src/testing/testing.go:777 +0x16d
  testing.runTests()
      GOROOT/src/testing/testing.go:1061 +0x4e1
  testing.(*M).Run()
      GOROOT/src/testing/testing.go:978 +0x2cd
  main.main()
      bazel-out/k8-fastbuild/bin/beacon-chain/sync/linux_amd64_race_stripped/go_default_test~/testmain.go:97 +0x28e

Goroutine 36 (running) created at:
  github.com/prysmaticlabs/prysm/beacon-chain/sync.TestSavingBlocksInSync()
      beacon-chain/sync/service_test.go:758 +0x212
  testing.tRunner()
      GOROOT/src/testing/testing.go:777 +0x16d

There was a problem with reusing msg1 in the test and changing members while the initialization goroutine was still active. It is fixed by generating different block response messages for each assertion.

codecov · 2018-08-08T16:03:34Z

Codecov Report

Merging #390 into master will decrease coverage by 0.22%.
The diff coverage is n/a.

@@            Coverage Diff             @@
##           master     #390      +/-   ##
==========================================
- Coverage   52.91%   52.69%   -0.23%     
==========================================
  Files          33       33              
  Lines        2695     2695              
==========================================
- Hits         1426     1420       -6     
- Misses       1098     1105       +7     
+ Partials      171      170       -1

Impacted Files	Coverage Δ
client/contracts/sharding_manager.go	`24.61% <0%> (-1.93%)`	⬇️
beacon-chain/rpc/service.go	`100% <0%> (+8.88%)`	⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 2060d29...95e8de2. Read the comment docs.

prestonvanloon · 2018-08-09T02:17:23Z

Thanks for this! Does this solve all of the race condition issues or just one?

If it solves all, can you add --features=race to the travis test?

fgimenez · 2018-08-09T06:27:24Z

Does this solve all of the race condition issues or just one?

@prestonvanloon just one, there are currently 4 race conditions on master:

INFO: 104 processes: 104 linux-sandbox.
//beacon-chain/blockchain:go_default_test                       (cached) PASSED in 1.2s
//beacon-chain/powchain:go_default_test                         (cached) PASSED in 1.2s
//beacon-chain/simulator:go_default_test                        (cached) PASSED in 1.2s
//beacon-chain/utils:go_default_test                            (cached) PASSED in 1.1s
//client/attester:go_default_test                               (cached) PASSED in 1.5s
//client/contracts:go_default_test                              (cached) PASSED in 296.9s
//client/mainchain:go_default_test                              (cached) PASSED in 3.2s
//client/observer:go_default_test                               (cached) PASSED in 1.8s
//client/params:go_default_test                                 (cached) PASSED in 1.1s
//client/txpool:go_default_test                                 (cached) PASSED in 1.1s
//client/types:go_default_test                                  (cached) PASSED in 1.2s
//contracts:go_default_test                                     (cached) PASSED in 1.4s
//shared:go_default_test                                        (cached) PASSED in 18.1s
//shared/cmd:go_default_test                                    (cached) PASSED in 1.2s
//shared/database:go_default_test                               (cached) PASSED in 1.4s
//shared/p2p:go_feed_concurrent_write_test                      (cached) PASSED in 1.7s
//beacon-chain/node:go_default_test                                      PASSED in 1.9s
//beacon-chain/rpc:go_default_test                                       PASSED in 1.1s
//client/node:go_default_test                                            PASSED in 1.8s
//client/rpcclient:go_default_test                                       PASSED in 1.1s
//beacon-chain/sync:go_default_test                                      FAILED in 5 out of 5 in 0.2s
  Stats over 5 runs: max = 0.2s, min = 0.1s, avg = 0.2s, dev = 0.0s
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/beacon-chain/sync/go_default_test/test_attempts/attempt_1.log
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/beacon-chain/sync/go_default_test/test_attempts/attempt_2.log
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/beacon-chain/sync/go_default_test/test_attempts/attempt_3.log
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/beacon-chain/sync/go_default_test/test_attempts/attempt_4.log
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/beacon-chain/sync/go_default_test/test.log
//client/proposer:go_default_test                                        FAILED in 5 out of 5 in 3.8s
  Stats over 5 runs: max = 3.8s, min = 3.7s, avg = 3.8s, dev = 0.1s
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/client/proposer/go_default_test/test_attempts/attempt_1.log
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/client/proposer/go_default_test/test_attempts/attempt_2.log
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/client/proposer/go_default_test/test_attempts/attempt_3.log
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/client/proposer/go_default_test/test_attempts/attempt_4.log
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/client/proposer/go_default_test/test.log
//client/syncer:go_default_test                                          FAILED in 5 out of 5 in 0.9s
  Stats over 5 runs: max = 0.9s, min = 0.9s, avg = 0.9s, dev = 0.0s
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/client/syncer/go_default_test/test_attempts/attempt_1.log
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/client/syncer/go_default_test/test_attempts/attempt_2.log
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/client/syncer/go_default_test/test_attempts/attempt_3.log
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/client/syncer/go_default_test/test_attempts/attempt_4.log
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/client/syncer/go_default_test/test.log
//shared/p2p:go_default_test                                             FAILED in 5 out of 5 in 1.7s
  Stats over 5 runs: max = 1.7s, min = 1.3s, avg = 1.5s, dev = 0.2s
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/shared/p2p/go_default_test/test_attempts/attempt_1.log
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/shared/p2p/go_default_test/test_attempts/attempt_2.log
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/shared/p2p/go_default_test/test_attempts/attempt_3.log
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/shared/p2p/go_default_test/test_attempts/attempt_4.log
  /home/fgimenez/.cache/bazel/_bazel_fgimenez/512843e3dd6bfc3af7fbee03058a93ee/execroot/__main__/bazel-out/k8-fastbuild/testlogs/shared/p2p/go_default_test/test.log

This PR solves //beacon-chain/sync:go_default_test. I think we can solve //client/syncer:go_default_test and part of //client/proposer:go_default_test too, will propose PRs for them next.

The rest of the issues come from the libp2p-go thirdparty library. The problem is tracked in this upstream issue libp2p/go-libp2p#257, they are aiming to switch the mdns library but seem to be blocked by grandcat/zeroconf#38

While this is not solved we could add the --features=race to travis command as you suggest and change the bazel config for the tests that are known to be racy, similar to what we did here https://github.com/prysmaticlabs/prysm/pull/321/files#diff-f127b9ba81d65ec476bc4edb33289780 but the other way around (setting race=off for the racy tests). This way the race detector would be enabled by default, WDYT?

prestonvanloon · 2018-08-09T12:14:33Z

OK, this is great progress nonetheless.

I recommend adding a race testing exclusion on those targets for now:

    race = "off", # TODO(#377): fix issues with race detection testing.

And adding --features=race to the travis yaml. Maybe this will prevent future issues while we work through the existing ones.
Thanks!

terencechain · 2018-08-09T16:02:18Z

beacon-chain/sync/service_test.go

-		SlotNumber:            uint64(20),
-		CrystallizedStateHash: crystallizedStateHash[:],
-	}
+	getBlockResponseMsg := func(slotNumber uint64) p2p.Message {


This is neat!

fgimenez · 2018-08-09T17:24:46Z

@prestonvanloon done, PTAL.

The racy tests are added to specific racy_tests.go files, and those are configured to be run with race=off in the respective BUILD.bazel files.

I've added the race feature to .travis-bazelrc so that it's easier to reproduce CI conditions locally, let me know what do you think.

fgimenez · 2018-08-09T18:39:57Z

just pushed changes to disable race detector on client/contracts, was timing out with it.

prestonvanloon

Rather than lumping all of the package tests into one test, racy_test.go.

What do you think about having multiple so it’s easy to know where they go after the problem has been solved?

service_norace_test.go
discovery_norace_test.go

Etc

fgimenez · 2018-08-10T08:09:43Z

@prestonvanloon great suggestion, done PTAL.

terencechain

LGTM

fgimenez · 2018-08-12T16:11:12Z

I have ready changes for preventing the client/syncer race, should I push them here or in a separate PR once this one is merged? The changes in this one for enabling the race detector by default would be required to verify that the fix works.

prestonvanloon · 2018-08-12T20:15:46Z

@fgimenez In another PR please. I'll merge this now

fgimenez · 2018-08-13T05:56:52Z

With the removal of client/syncer in #395 the only remaining race is in shared/p2p caused by libp2p-go. I'll keep an eye on libp2p/go-libp2p#257 and grandcat/zeroconf#38.

terencechain reviewed Aug 9, 2018

View reviewed changes

prestonvanloon reviewed Aug 9, 2018

View reviewed changes

terencechain approved these changes Aug 10, 2018

View reviewed changes

fgimenez added 8 commits August 12, 2018 20:32

fix beacon-chain/sync test race

1cd443b

address review comments

777959c

remove unused file

aa6a720

gazelle

4ba9f27

disable race for client/contracts

8812493

address review comments

845e2b3

fix conflict

5a9f257

remove duplicated deps, embed

ee29d53

fgimenez force-pushed the fix-beaconchain-sync-test-race branch from cc5559d to ee29d53 Compare August 12, 2018 18:38

remove unneeded file

95e8de2

prestonvanloon merged commit dd29481 into prysmaticlabs:master Aug 12, 2018

fgimenez deleted the fix-beaconchain-sync-test-race branch August 12, 2018 20:28

This was referenced Aug 13, 2018

Add Race Detection to CI #378

Closed

Tests Fail With Race Detection #377

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix beacon-chain/sync Test Race #390

Fix beacon-chain/sync Test Race #390

fgimenez commented Aug 8, 2018

codecov bot commented Aug 8, 2018 •

edited

prestonvanloon commented Aug 9, 2018

fgimenez commented Aug 9, 2018

prestonvanloon commented Aug 9, 2018

terencechain Aug 9, 2018

fgimenez commented Aug 9, 2018

fgimenez commented Aug 9, 2018

prestonvanloon left a comment

fgimenez commented Aug 10, 2018

terencechain left a comment

fgimenez commented Aug 12, 2018

prestonvanloon commented Aug 12, 2018

fgimenez commented Aug 13, 2018

Fix beacon-chain/sync Test Race #390

Fix beacon-chain/sync Test Race #390

Conversation

fgimenez commented Aug 8, 2018

codecov bot commented Aug 8, 2018 • edited

Codecov Report

prestonvanloon commented Aug 9, 2018

fgimenez commented Aug 9, 2018

prestonvanloon commented Aug 9, 2018

terencechain Aug 9, 2018

Choose a reason for hiding this comment

fgimenez commented Aug 9, 2018

fgimenez commented Aug 9, 2018

prestonvanloon left a comment

Choose a reason for hiding this comment

fgimenez commented Aug 10, 2018

terencechain left a comment

Choose a reason for hiding this comment

fgimenez commented Aug 12, 2018

prestonvanloon commented Aug 12, 2018

fgimenez commented Aug 13, 2018

codecov bot commented Aug 8, 2018 •

edited