Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Race detected during execution of the initial version tests #20

Closed
dnkolegov opened this issue Apr 22, 2022 · 1 comment · Fixed by #28
Closed

Race detected during execution of the initial version tests #20

dnkolegov opened this issue Apr 22, 2022 · 1 comment · Fixed by #28
Assignees
@matejpavlovic

Comments

@dnkolegov
Copy link
Contributor

Steps to reproduce:

  1. git reset 3ba8221c2b44624157cb386a9552be90ea3eace1
  2. go test -race
  3. You will see something like that:
•Creating temp dir: /var/folders/p_/rj3w31dn05942p50hxzy03fc0000gn/T/mir-deployment-test.2218592999
Node 0: running
Connecting to node: 127.0.0.1:20000
Node 0: ReqRec: Listening for request connections on port 20000
Node 0: ISS: PBFT: Proposing. epoch=0 instance=0 sn=0 batchSize=0
Node 0: ISS: Delivering entry. sn=0 nReq=0
Node 0: ISS: PBFT: Proposing. epoch=0 instance=0 sn=1 batchSize=0
Node 0: ISS: Delivering entry. sn=1 nReq=0
Node 0: ISS: PBFT: Proposing. epoch=0 instance=0 sn=2 batchSize=0
Node 0: ISS: Delivering entry. sn=2 nReq=0
Node 0: ISS: PBFT: Proposing. epoch=0 instance=0 sn=3 batchSize=0
Node 0: ISS: Delivering entry. sn=3 nReq=0
Node 0: ISS: PBFT: Proposing. epoch=0 instance=0 sn=4 batchSize=0
Node 0: ISS: Delivering entry. sn=4 nReq=0
Node 0: ISS: PBFT: Proposing. epoch=0 instance=0 sn=5 batchSize=0
Node 0: ISS: Delivering entry. sn=5 nReq=0
Node 0: ISS: PBFT: Proposing. epoch=0 instance=0 sn=6 batchSize=0
Node 0: ISS: Delivering entry. sn=6 nReq=0
Node 0: ISS: PBFT: Proposing. epoch=0 instance=0 sn=7 batchSize=0
Node 0: ISS: Delivering entry. sn=7 nReq=0
Node 0: ISS: PBFT: Proposing. epoch=0 instance=0 sn=8 batchSize=0
Node 0: ISS: Delivering entry. sn=8 nReq=0
Node 0: ISS: PBFT: Proposing. epoch=0 instance=0 sn=9 batchSize=0
Node %!d(types.NodeID=0) (127.0.0.1:20000) connected.
Node 0: ReqRec: Incoming connection from 127.0.0.1:51983
Node 0: ReqRec: Received request clId=1 reqNo=0 authLen=71
Node 0: ReqRec: Received request clId=1 reqNo=1 authLen=72
Node 0: ReqRec: Received request clId=1 reqNo=2 authLen=71
Node 0: ReqRec: Received request clId=1 reqNo=3 authLen=71
Node 0: ReqRec: Received request clId=1 reqNo=4 authLen=70
Node 0: ReqRec: Received request clId=1 reqNo=5 authLen=71
Node 0: ReqRec: Received request clId=1 reqNo=6 authLen=69
Node 0: ReqRec: Received request clId=1 reqNo=7 authLen=71
Node 0: ReqRec: Received request clId=1 reqNo=8 authLen=72
Node 0: ReqRec: Received request clId=1 reqNo=9 authLen=72
Node 0: ISS: Delivering entry. sn=9 nReq=0
Node 0: ISS: PBFT: Proposing. epoch=1 instance=1 sn=10 batchSize=4
Node 0: ISS: PBFT: Proposing. epoch=1 instance=1 sn=11 batchSize=4
Node 0: ISS: New stable checkpoint. epoch=1 sn=10 replacingEpoch=0 replacingSn=0
Node 0: ISS: PBFT: Proposing. epoch=1 instance=1 sn=12 batchSize=2
Node 0: ISS: Delivering entry. sn=10 nReq=4
Processed requests: 1
Processed requests: 2
Processed requests: 3
Processed requests: 4
Node 0: ISS: Delivering entry. sn=11 nReq=4
Processed requests: 5
Processed requests: 6
Processed requests: 7
Processed requests: 8
Node 0: ISS: Delivering entry. sn=12 nReq=2
Processed requests: 9
Processed requests: 10
Node 0: ISS: PBFT: Proposing. epoch=1 instance=1 sn=13 batchSize=0
Node 0: ISS: Delivering entry. sn=13 nReq=0
Node 0: ISS: PBFT: Proposing. epoch=1 instance=1 sn=14 batchSize=0
Node 0: ISS: Delivering entry. sn=14 nReq=0
Node 0: ISS: PBFT: Proposing. epoch=1 instance=1 sn=15 batchSize=0
Node 0: ISS: Delivering entry. sn=15 nReq=0
Node 0: ISS: PBFT: Proposing. epoch=1 instance=1 sn=16 batchSize=0
Node 0: ISS: Delivering entry. sn=16 nReq=0
Node 0: ISS: PBFT: Proposing. epoch=1 instance=1 sn=17 batchSize=0
Node 0: ISS: Delivering entry. sn=17 nReq=0
Node 0: ISS: PBFT: Proposing. epoch=1 instance=1 sn=18 batchSize=0
Node 0: ISS: Delivering entry. sn=18 nReq=0
Node 0: ISS: PBFT: Proposing. epoch=1 instance=1 sn=19 batchSize=0
Node 0: ISS: Delivering entry. sn=19 nReq=0
Node 0: ISS: New stable checkpoint. epoch=2 sn=20 replacingEpoch=1 replacingSn=10
==================
WARNING: DATA RACE
Write at 0x00c000560cd0 by goroutine 7:
  google.golang.org/grpc.(*clientStream).CloseSend()
      /Users/alpha/go/pkg/mod/google.golang.org/grpc@v1.40.0/stream.go:857 +0x4c
  github.com/filecoin-project/mir/pkg/requestreceiver.(*requestReceiverListenClient).CloseAndRecv()
      /Users/alpha/Projects/mir/pkg/requestreceiver/requestreceiver_grpc.pb.go:61 +0x44
  github.com/filecoin-project/mir/pkg/dummyclient.(*DummyClient).Disconnect()
      /Users/alpha/Projects/mir/pkg/dummyclient/dummyclient.go:158 +0xbc
  github.com/filecoin-project/mir/pkg/deploytest.(*Deployment).Run()
      /Users/alpha/Projects/mir/pkg/deploytest/deployment.go:213 +0x574
  github.com/filecoin-project/mir_test.glob..func1.2()
      /Users/alpha/Projects/mir/mirbft_test.go:87 +0x360
  runtime.call16()
      /opt/homebrew/Cellar/go/1.18/libexec/src/runtime/asm_arm64.s:507 +0x78
  reflect.Value.Call()
      /opt/homebrew/Cellar/go/1.18/libexec/src/reflect/value.go:339 +0x94
  github.com/onsi/ginkgo/extensions/table.TableEntry.generateIt.func1()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/extensions/table/table_entry.go:40 +0x6c
Run returned!
  github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/internal/leafnodes/runner.go:113 +0xb0
  github.com/onsi/ginkgo/internal/leafnodes.(*runner).run()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/internal/leafnodes/runner.go:64 +0xf8
  github.com/onsi/ginkgo/internal/leafnodes.(*ItNode).Run()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/internal/leafnodes/it_node.go:26 +0x6c
  github.com/onsi/ginkgo/internal/spec.(*Spec).runSample()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/internal/spec/spec.go:215 +0x248
  github.com/onsi/ginkgo/internal/spec.(*Spec).Run()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/internal/spec/spec.go:138 +0x148
  github.com/onsi/ginkgo/internal/specrunner.(*SpecRunner).runSpec()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/internal/specrunner/spec_runner.go:200 +0x138
  github.com/onsi/ginkgo/internal/specrunner.(*SpecRunner).runSpecs()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/internal/specrunner/spec_runner.go:170 +0x1f8
  github.com/onsi/ginkgo/internal/specrunner.(*SpecRunner).Run()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/internal/specrunner/spec_runner.go:66 +0x120
  github.com/onsi/ginkgo/internal/suite.(*Suite).Run()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/internal/suite/suite.go:62 +0x514
Node 0: ReqRec: Stopping request receiver.  github.com/onsi/ginkgo.RunSpecsWithCustomReporters()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/ginkgo_dsl.go:221 +0x170
  github.com/onsi/ginkgo.RunSpecs()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/ginkgo_dsl.go:202 +0x60

  github.com/filecoin-project/mir_test.TestMir()
      /Users/alpha/Projects/mir/mirbft_suite_test.go:66 +0x1f0
  testing.tRunner()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1439 +0x18c
  testing.(*T).Run.func1()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1486 +0x44

Previous read at 0x00c000560cd0 by goroutine 140:
  google.golang.org/grpc.(*clientStream).SendMsg()
      /Users/alpha/go/pkg/mod/google.golang.org/grpc@v1.40.0/stream.go:776 +0xd8
  github.com/filecoin-project/mir/pkg/requestreceiver.(*requestReceiverListenClient).Send()
      /Users/alpha/Projects/mir/pkg/requestreceiver/requestreceiver_grpc.pb.go:57 +0x58
  github.com/filecoin-project/mir/pkg/dummyclient.(*DummyClient).SubmitRequest()
      /Users/alpha/Projects/mir/pkg/dummyclient/dummyclient.go:131 +0x5d0
  github.com/filecoin-project/mir/pkg/deploytest.submitDummyRequests()
      /Users/alpha/Projects/mir/pkg/deploytest/deployment.go:262 +0xa0
  github.com/filecoin-project/mir/pkg/deploytest.(*Deployment).Run.func2()
      /Users/alpha/Projects/mir/pkg/deploytest/deployment.go:203 +0x64
  github.com/filecoin-project/mir/pkg/deploytest.(*Deployment).Run.func5()
      /Users/alpha/Projects/mir/pkg/deploytest/deployment.go:204 +0x48

Goroutine 7 (running) created at:
  testing.(*T).Run()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1486 +0x560
  testing.runTests.func1()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1839 +0x94
  testing.tRunner()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1439 +0x18c
  testing.runTests()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1837 +0x6c8
  testing.(*M).Run()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1719 +0x878
  main.main()
      _testmain.go:49 +0x2fc

Goroutine 140 (finished) created at:
  github.com/filecoin-project/mir/pkg/deploytest.(*Deployment).Run()
      /Users/alpha/Projects/mir/pkg/deploytest/deployment.go:201 +0x3c4
  github.com/filecoin-project/mir_test.glob..func1.2()
      /Users/alpha/Projects/mir/mirbft_test.go:87 +0x360
  runtime.call16()
      /opt/homebrew/Cellar/go/1.18/libexec/src/runtime/asm_arm64.s:507 +0x78
  reflect.Value.Call()
      /opt/homebrew/Cellar/go/1.18/libexec/src/reflect/value.go:339 +0x94
  github.com/onsi/ginkgo/extensions/table.TableEntry.generateIt.func1()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/extensions/table/table_entry.go:40 +0x6c
  github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/internal/leafnodes/runner.go:113 +0xb0
  github.com/onsi/ginkgo/internal/leafnodes.(*runner).run()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/internal/leafnodes/runner.go:64 +0xf8
  github.com/onsi/ginkgo/internal/leafnodes.(*ItNode).Run()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/internal/leafnodes/it_node.go:26 +0x6c
  github.com/onsi/ginkgo/internal/spec.(*Spec).runSample()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/internal/spec/spec.go:215 +0x248
  github.com/onsi/ginkgo/internal/spec.(*Spec).Run()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/internal/spec/spec.go:138 +0x148
  github.com/onsi/ginkgo/internal/specrunner.(*SpecRunner).runSpec()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/internal/specrunner/spec_runner.go:200 +0x138
  github.com/onsi/ginkgo/internal/specrunner.(*SpecRunner).runSpecs()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/internal/specrunner/spec_runner.go:170 +0x1f8
  github.com/onsi/ginkgo/internal/specrunner.(*SpecRunner).Run()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/internal/specrunner/spec_runner.go:66 +0x120
  github.com/onsi/ginkgo/internal/suite.(*Suite).Run()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/internal/suite/suite.go:62 +0x514
  github.com/onsi/ginkgo.RunSpecsWithCustomReporters()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/ginkgo_dsl.go:221 +0x170
  github.com/onsi/ginkgo.RunSpecs()
      /Users/alpha/go/pkg/mod/github.com/onsi/ginkgo@v1.8.0/ginkgo_dsl.go:202 +0x60
  github.com/filecoin-project/mir_test.TestMir()
      /Users/alpha/Projects/mir/mirbft_suite_test.go:66 +0x1f0
  testing.tRunner()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1439 +0x18c
  testing.(*T).Run.func1()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1486 +0x44
==================
Node 0: ReqRec: Connection terminated: 127.0.0.1:51983 (EOF)
Node 0: ReqRec: Request receiver stopped.
Could not close connection to node %!d(types.NodeID=0)
Intercepted events written to event log: 420
Node 0: exit with exitErr=stopped at caller request
All go routines shut down
Test finished.

--- FAIL: TestMir (22.75s)
    testing.go:1312: race detected during execution of test
FAIL
exit status 1
FAIL	github.com/filecoin-project/mir	23.507s
@matejpavlovic
Copy link
Contributor

The race is caused by one thread sending requests through the dummy client and a different one closing the connection when the test is done in /pkg/deploytest/deployment.go.

@matejpavlovic matejpavlovic self-assigned this Apr 25, 2022
@matejpavlovic matejpavlovic mentioned this issue Apr 26, 2022
Merged
@matejpavlovic matejpavlovic mentioned this issue May 2, 2022
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@matejpavlovic matejpavlovic

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix race condition in deployment test matejpavlovic/mir
2 participants
@dnkolegov @matejpavlovic