ssv icon indicating copy to clipboard operation
ssv copied to clipboard

Published 20 hours ago • verified publisher icon ssvlabs

Data Race in tests

Open amirylm opened this issue 3 years ago • 0 comments

There is a data race on currentInstance:

=== RUN   TestForceDecided
badger 2021/08/08 14:09:11 INFO: Set nextTxnTs to 0
2021-08-08T14:09:11.542336Z	INFO	kv/badger.go:45	Badger db initialized	{"app": "simulator"}
seed - 16413883976378449900
2021-08-08T14:09:12.566678Z	INFO	ibft/instance.go:142	Node is starting iBFT instance	{"app": "simulator", "node_id": 1, "seq_num": 4, "pubKey": "87cdb0dc6db0945478462a00f30d3e8a497a5b03695cea73b72762d08358994ec0f4bbe171cf9c616cda756bec6d3470", "Lambda": "6c616d6264615f3131"}
2021-08-08T14:09:12.766910Z	INFO	ibft/event_loop.go:153	started timeout clock	{"app": "simulator", "node_id": 1, "seq_num": 4, "pubKey": "87cdb0dc6db0945478462a00f30d3e8a497a5b03695cea73b72762d08358994ec0f4bbe171cf9c616cda756bec6d3470", "seconds": 3, "round": 1}
==================
WARNING: DATA RACE
Read at 0x00c0004f0488 by goroutine 115:
  github.com/bloxapp/ssv/ibft.(*ibftImpl).decidedForCurrentInstance()
      /home/runner/work/ssv/ssv/ibft/ibft_decided.go:114 +0x77
  github.com/bloxapp/ssv/ibft.(*ibftImpl).forceDecideCurrentInstance()
      /home/runner/work/ssv/ssv/ibft/ibft_decided.go:85 +0x153
  github.com/bloxapp/ssv/ibft.(*ibftImpl).ProcessDecidedMessage()
      /home/runner/work/ssv/ssv/ibft/ibft_decided.go:66 +0xb14
  github.com/bloxapp/ssv/ibft.TestForceDecided.func1()
      /home/runner/work/ssv/ssv/ibft/ibft_decided_test.go:281 +0x1e4

Previous write at 0x00c0004f0488 by goroutine 22:
  github.com/bloxapp/ssv/ibft.(*ibftImpl).startInstanceWithOptions()
      /home/runner/work/ssv/ssv/ibft/ibft_running_instance.go:12 +0xb0
  github.com/bloxapp/ssv/ibft.(*ibftImpl).StartInstance()
      /home/runner/work/ssv/ssv/ibft/ibft.go:115 +0x4b0
  github.com/bloxapp/ssv/ibft.TestForceDecided()
      /home/runner/work/ssv/ssv/ibft/ibft_decided_test.go:290 +0x678
  testing.tRunner()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1123 +0x202

Goroutine 115 (running) created at:
  github.com/bloxapp/ssv/ibft.TestForceDecided()
      /home/runner/work/ssv/ssv/ibft/ibft_decided_test.go:272 +0x336
  testing.tRunner()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1123 +0x202

Goroutine 22 (running) created at:
  testing.(*T).Run()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1168 +0x5bb
  testing.runTests.func1()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1439 +0xa6
  testing.tRunner()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1123 +0x202
  testing.runTests()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1437 +0x612
  testing.(*M).Run()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1345 +0x3b3
  main.main()
      _testmain.go:705 +0x356
==================
==================
WARNING: DATA RACE
Read at 0x00c000b12108 by goroutine 115:
  github.com/bloxapp/ssv/ibft.(*ibftImpl).decidedForCurrentInstance()
      /home/runner/work/ssv/ssv/ibft/ibft_decided.go:114 +0xe4
  github.com/bloxapp/ssv/ibft.(*ibftImpl).forceDecideCurrentInstance()
      /home/runner/work/ssv/ssv/ibft/ibft_decided.go:85 +0x153
  github.com/bloxapp/ssv/ibft.(*ibftImpl).ProcessDecidedMessage()
      /home/runner/work/ssv/ssv/ibft/ibft_decided.go:66 +0xb14
  github.com/bloxapp/ssv/ibft.TestForceDecided.func1()
      /home/runner/work/ssv/ssv/ibft/ibft_decided_test.go:281 +0x1e4

Previous write at 0x00c000b12108 by goroutine 22:
  github.com/bloxapp/ssv/ibft.NewInstance()
      /home/runner/work/ssv/ssv/ibft/instance.go:77 +0xc11
  github.com/bloxapp/ssv/ibft.(*ibftImpl).startInstanceWithOptions()
      /home/runner/work/ssv/ssv/ibft/ibft_running_instance.go:12 +0x84
  github.com/bloxapp/ssv/ibft.(*ibftImpl).StartInstance()
      /home/runner/work/ssv/ssv/ibft/ibft.go:115 +0x4b0
  github.com/bloxapp/ssv/ibft.TestForceDecided()
      /home/runner/work/ssv/ssv/ibft/ibft_decided_test.go:290 +0x678
  testing.tRunner()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1123 +0x202

Goroutine 115 (running) created at:
  github.com/bloxapp/ssv/ibft.TestForceDecided()
      /home/runner/work/ssv/ssv/ibft/ibft_decided_test.go:272 +0x336
  testing.tRunner()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1123 +0x202

Goroutine 22 (running) created at:
  testing.(*T).Run()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1168 +0x5bb
  testing.runTests.func1()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1439 +0xa6
  testing.tRunner()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1123 +0x202
  testing.runTests()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1437 +0x612
  testing.(*M).Run()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1345 +0x3b3
  main.main()
      _testmain.go:705 +0x356
==================
==================
WARNING: DATA RACE
Read at 0x00c0002da048 by goroutine 115:
  github.com/bloxapp/ssv/ibft.(*ibftImpl).decidedForCurrentInstance()
      /home/runner/work/ssv/ssv/ibft/ibft_decided.go:114 +0x104
  github.com/bloxapp/ssv/ibft.(*ibftImpl).forceDecideCurrentInstance()
      /home/runner/work/ssv/ssv/ibft/ibft_decided.go:85 +0x153
  github.com/bloxapp/ssv/ibft.(*ibftImpl).ProcessDecidedMessage()
      /home/runner/work/ssv/ssv/ibft/ibft_decided.go:66 +0xb14
  github.com/bloxapp/ssv/ibft.TestForceDecided.func1()
      /home/runner/work/ssv/ssv/ibft/ibft_decided_test.go:281 +0x1e4

Previous write at 0x00c0002da048 by goroutine 22:
  github.com/bloxapp/ssv/ibft.NewInstance()
      /home/runner/work/ssv/ssv/ibft/instance.go:79 +0xcba
  github.com/bloxapp/ssv/ibft.(*ibftImpl).startInstanceWithOptions()
      /home/runner/work/ssv/ssv/ibft/ibft_running_instance.go:12 +0x84
  github.com/bloxapp/ssv/ibft.(*ibftImpl).StartInstance()
      /home/runner/work/ssv/ssv/ibft/ibft.go:115 +0x4b0
  github.com/bloxapp/ssv/ibft.TestForceDecided()
      /home/runner/work/ssv/ssv/ibft/ibft_decided_test.go:290 +0x678
  testing.tRunner()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1123 +0x202

Goroutine 115 (running) created at:
  github.com/bloxapp/ssv/ibft.TestForceDecided()
      /home/runner/work/ssv/ssv/ibft/ibft_decided_test.go:272 +0x336
  testing.tRunner()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1123 +0x202

Goroutine 22 (running) created at:
  testing.(*T).Run()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1168 +0x5bb
  testing.runTests.func1()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1439 +0xa6
  testing.tRunner()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1123 +0x202
  testing.runTests()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1437 +0x612
  testing.(*M).Run()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1345 +0x3b3
  main.main()
      _testmain.go:705 +0x356
==================
==================
WARNING: DATA RACE
Read at 0x00c000b121a0 by goroutine 115:
  github.com/bloxapp/ssv/ibft.(*Instance).ForceDecide()
      /home/runner/work/ssv/ssv/ibft/instance.go:170 +0xe6
  github.com/bloxapp/ssv/ibft.(*ibftImpl).forceDecideCurrentInstance()
      /home/runner/work/ssv/ssv/ibft/ibft_decided.go:88 +0x1fa
  github.com/bloxapp/ssv/ibft.(*ibftImpl).ProcessDecidedMessage()
      /home/runner/work/ssv/ssv/ibft/ibft_decided.go:66 +0xb14
  github.com/bloxapp/ssv/ibft.TestForceDecided.func1()
      /home/runner/work/ssv/ssv/ibft/ibft_decided_test.go:281 +0x1e4

Previous write at 0x00c000b121a0 by goroutine 22:
  github.com/bloxapp/ssv/ibft.NewInstance()
      /home/runner/work/ssv/ssv/ibft/instance.go:77 +0xc11
  github.com/bloxapp/ssv/ibft.(*ibftImpl).startInstanceWithOptions()
      /home/runner/work/ssv/ssv/ibft/ibft_running_instance.go:12 +0x84
  github.com/bloxapp/ssv/ibft.(*ibftImpl).StartInstance()
      /home/runner/work/ssv/ssv/ibft/ibft.go:115 +0x4b0
  github.com/bloxapp/ssv/ibft.TestForceDecided()
      /home/runner/work/ssv/ssv/ibft/ibft_decided_test.go:290 +0x678
  testing.tRunner()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1123 +0x202

Goroutine 115 (running) created at:
  github.com/bloxapp/ssv/ibft.TestForceDecided()
      /home/runner/work/ssv/ssv/ibft/ibft_decided_test.go:272 +0x336
  testing.tRunner()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1123 +0x202

Goroutine 22 (running) created at:
  testing.(*T).Run()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1168 +0x5bb
  testing.runTests.func1()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1439 +0xa6
  testing.tRunner()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1123 +0x202
  testing.runTests()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1437 +0x612
  testing.(*M).Run()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1345 +0x3b3
  main.main()
      _testmain.go:705 +0x356
==================
==================
WARNING: DATA RACE
Write at 0x00c000cca590 by goroutine 115:
  sync/atomic.CompareAndSwapInt32()
      /opt/hostedtoolcache/go/1.15.14/x64/src/runtime/race_amd64.s:293 +0xb
  sync.(*Mutex).Lock()
      /opt/hostedtoolcache/go/1.15.14/x64/src/sync/mutex.go:74 +0x4d
  github.com/bloxapp/ssv/ibft/eventqueue.(*queue).Add()
      /home/runner/work/ssv/ssv/ibft/eventqueue/queue.go:35 +0x84
  github.com/bloxapp/ssv/ibft.(*Instance).ForceDecide()
      /home/runner/work/ssv/ssv/ibft/instance.go:170 +0x10d
  github.com/bloxapp/ssv/ibft.(*ibftImpl).forceDecideCurrentInstance()
      /home/runner/work/ssv/ssv/ibft/ibft_decided.go:88 +0x1fa
  github.com/bloxapp/ssv/ibft.(*ibftImpl).ProcessDecidedMessage()
      /home/runner/work/ssv/ssv/ibft/ibft_decided.go:66 +0xb14
  github.com/bloxapp/ssv/ibft.TestForceDecided.func1()
      /home/runner/work/ssv/ssv/ibft/ibft_decided_test.go:281 +0x1e4

Previous write at 0x00c000cca590 by goroutine 22:
  github.com/bloxapp/ssv/ibft/eventqueue.New()
      /home/runner/work/ssv/ssv/ibft/instance.go:100 +0xb26
  github.com/bloxapp/ssv/ibft.NewInstance()
      /home/runner/work/ssv/ssv/ibft/instance.go:100 +0x10cd
  github.com/bloxapp/ssv/ibft.(*ibftImpl).startInstanceWithOptions()
      /home/runner/work/ssv/ssv/ibft/ibft_running_instance.go:12 +0x84
  github.com/bloxapp/ssv/ibft.(*ibftImpl).StartInstance()
      /home/runner/work/ssv/ssv/ibft/ibft.go:115 +0x4b0
  github.com/bloxapp/ssv/ibft.TestForceDecided()
      /home/runner/work/ssv/ssv/ibft/ibft_decided_test.go:290 +0x678
  testing.tRunner()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1123 +0x202

Goroutine 115 (running) created at:
  github.com/bloxapp/ssv/ibft.TestForceDecided()
      /home/runner/work/ssv/ssv/ibft/ibft_decided_test.go:272 +0x336
  testing.tRunner()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1123 +0x202

Goroutine 22 (running) created at:
  testing.(*T).Run()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1168 +0x5bb
  testing.runTests.func1()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1439 +0xa6
  testing.tRunner()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1123 +0x202
  testing.runTests()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1437 +0x612
  testing.(*M).Run()
      /opt/hostedtoolcache/go/1.15.14/x64/src/testing/testing.go:1345 +0x3b3
  main.main()
      _testmain.go:705 +0x356
==================
2021-08-08T14:09:13.167490Z	INFO	ibft/instance.go:171	trying to force instance decision.	{"app": "simulator", "node_id": 1, "seq_num": 4, "pubKey": "87cdb0dc6db0945478462a00f30d3e8a497a5b03695cea73b72762d08358994ec0f4bbe171cf9c616cda756bec6d3470"}
2021-08-08T14:09:13.170296Z	INFO	ibft/commit.go:43	received valid decided message for round	{"app": "simulator", "node_id": 1, "seq_num": 4, "pubKey": "87cdb0dc6db0945478462a00f30d3e8a497a5b03695cea73b72762d08358994ec0f4bbe171cf9c616cda756bec6d3470", "sender_ibft_id": ", 1, 2, 3, 4", "round": 1}
2021-08-08T14:09:13.170500Z	INFO	ibft/commit.go:78	commit iBFT instance	{"app": "simulator", "node_id": 1, "seq_num": 4, "pubKey": "87cdb0dc6db0945478462a00f30d3e8a497a5b03695cea73b72762d08358994ec0f4bbe171cf9c616cda756bec6d3470", "Lambda": "6c616d6264615f3131", "round": 1, "got_votes": 1}
2021-08-08T14:09:13.170886Z	INFO	ibft/instance.go:190	stopping iBFT instance...	{"app": "simulator", "node_id": 1, "seq_num": 4, "pubKey": "87cdb0dc6db0945478462a00f30d3e8a497a5b03695cea73b72762d08358994ec0f4bbe171cf9c616cda756bec6d3470"}
2021-08-08T14:09:13.171077Z	INFO	ibft/event_loop.go:134	stopped timeout clock	{"app": "simulator", "node_id": 1, "seq_num": 4, "pubKey": "87cdb0dc6db0945478462a00f30d3e8a497a5b03695cea73b72762d08358994ec0f4bbe171cf9c616cda756bec6d3470", "round": 1}
2021-08-08T14:09:13.177073Z	INFO	ibft/ibft_running_instance.go:81	decided current instance	{"app": "simulator", "role": "ATTESTER", "identifier": "lambda_11", "seqNum": 4}
2021-08-08T14:09:13.177182Z	INFO	ibft/ibft_running_instance.go:84	current iBFT instance stopped, nilling currentInstance	{"app": "simulator", "role": "ATTESTER", "seqNum": 4}
2021-08-08T14:09:13.177210Z	INFO	ibft/instance.go:212	stopped iBFT instance	{"app": "simulator", "node_id": 1, "seq_num": 4, "pubKey": "87cdb0dc6db0945478462a00f30d3e8a497a5b03695cea73b72762d08358994ec0f4bbe171cf9c616cda756bec6d3470"}
2021-08-08T14:09:13.177327Z	INFO	ibft/event_loop.go:42	instance main event loop stopped	{"app": "simulator", "node_id": 1, "seq_num": 4, "pubKey": "87cdb0dc6db0945478462a00f30d3e8a497a5b03695cea73b72762d08358994ec0f4bbe171cf9c616cda756bec6d3470"}
2021-08-08T14:09:13.177411Z	INFO	ibft/event_loop.go:137	instance round timer loop stopped	{"app": "simulator", "node_id": 1, "seq_num": 4, "pubKey": "87cdb0dc6db0945478462a00f30d3e8a497a5b03695cea73b72762d08358994ec0f4bbe171cf9c616cda756bec6d3470"}
    testing.go:1038: race detected during execution of test
--- FAIL: TestForceDecided (1.65s)

amirylm avatar Aug 08 '21 14:08 amirylm