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 in TestServerRegisterPeer #2973

Closed
AnnaShaleva opened this issue Apr 14, 2023 · 1 comment · Fixed by #3307
Closed

Race in TestServerRegisterPeer #2973

AnnaShaleva opened this issue Apr 14, 2023 · 1 comment · Fixed by #3307
Labels
bug Something isn't working I4 No visible changes S4 Routine test Unit tests U2 Seriously planned
Milestone
v0.106.0

Comments

@AnnaShaleva
Copy link
Member 

2023-04-13T15:51:08.5219927Z === RUN   TestServerRegisterPeer
2023-04-13T15:51:08.5220513Z     logger.go:130: 2023-04-13T15:45:33.453Z	INFO	ExtensiblePoolSize is not set or wrong, using default value	{"ExtensiblePoolSize": 20}
2023-04-13T15:51:08.5221066Z     logger.go:130: 2023-04-13T15:45:33.453Z	INFO	bad AttemptConnPeers configured, using the default value	{"configured": 0, "actual": 20}
2023-04-13T15:51:08.5221462Z     logger.go:130: 2023-04-13T15:45:33.454Z	INFO	node started	{"blockHeight": 0, "headerHeight": 0}
2023-04-13T15:51:08.5221852Z     logger.go:130: 2023-04-13T15:45:33.454Z	INFO	node reached synchronized state, starting services
2023-04-13T15:51:08.5222248Z     logger.go:130: 2023-04-13T15:45:33.454Z	INFO	new peer connected	{"addr": "0.0.0.0:1", "peerCount": 1}
2023-04-13T15:51:08.5222332Z ==================
2023-04-13T15:51:08.5222424Z WARNING: DATA RACE
2023-04-13T15:51:08.5222551Z Read at 0x00c0004c6ba3 by goroutine 79:
2023-04-13T15:51:08.5222681Z   testing.(*common).logDepth()
2023-04-13T15:51:08.5222993Z       /opt/hostedtoolcache/go/1.18.10/x64/src/testing/testing.go:882 +0x4ce
2023-04-13T15:51:08.5223112Z   testing.(*common).log()
2023-04-13T15:51:08.5223413Z       /opt/hostedtoolcache/go/1.18.10/x64/src/testing/testing.go:869 +0x9c
2023-04-13T15:51:08.5223529Z   testing.(*common).Logf()
2023-04-13T15:51:08.5223814Z       /opt/hostedtoolcache/go/1.18.10/x64/src/testing/testing.go:920 +0x67
2023-04-13T15:51:08.5223920Z   testing.(*T).Logf()
2023-04-13T15:51:08.5224110Z       <autogenerated>:1 +0x75
2023-04-13T15:51:08.5224294Z   go.uber.org/zap/zaptest.testingWriter.Write()
2023-04-13T15:51:08.5224633Z       /home/runner/go/pkg/mod/go.uber.org/zap@v1.24.0/zaptest/logger.go:130 +0x12c
2023-04-13T15:51:08.5224797Z   go.uber.org/zap/zaptest.(*testingWriter).Write()
2023-04-13T15:51:08.5224941Z       <autogenerated>:1 +0x7e
2023-04-13T15:51:08.5225094Z   go.uber.org/zap/zapcore.(*ioCore).Write()
2023-04-13T15:51:08.5225463Z       /home/runner/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/core.go:99 +0x196
2023-04-13T15:51:08.5225638Z   go.uber.org/zap/zapcore.(*CheckedEntry).Write()
2023-04-13T15:51:08.5225962Z       /home/runner/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/entry.go:255 +0x2cc
2023-04-13T15:51:08.5226096Z   go.uber.org/zap.(*Logger).Warn()
2023-04-13T15:51:08.5226397Z       /home/runner/go/pkg/mod/go.uber.org/zap@v1.24.0/logger.go:228 +0x6d
2023-04-13T15:51:08.5226656Z   github.com/nspcc-dev/neo-go/pkg/network.(*Server).run()
2023-04-13T15:51:08.5227039Z       /home/runner/work/neo-go/neo-go/pkg/network/server.go:490 +0x12e8
2023-04-13T15:51:08.5227302Z   github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start()
2023-04-13T15:51:08.5227673Z       /home/runner/work/neo-go/neo-go/pkg/network/server.go:288 +0x646
2023-04-13T15:51:08.5228024Z   github.com/nspcc-dev/neo-go/pkg/network.TestServerStartAndShutdown.func1.2()
2023-04-13T15:51:08.5228401Z       /home/runner/work/neo-go/neo-go/pkg/network/server_test.go:94 +0x39
2023-04-13T15:51:08.5228418Z 
2023-04-13T15:51:08.5228565Z Previous write at 0x00c0004c6ba3 by goroutine 42:
2023-04-13T15:51:08.5228689Z   testing.tRunner.func1()
2023-04-13T15:51:08.5228994Z       /opt/hostedtoolcache/go/1.18.10/x64/src/testing/testing.go:1426 +0x7af
2023-04-13T15:51:08.5229115Z   runtime.deferreturn()
2023-04-13T15:51:08.5229410Z       /opt/hostedtoolcache/go/1.18.10/x64/src/runtime/panic.go:436 +0x32
2023-04-13T15:51:08.5229523Z   testing.(*T).Run.func1()
2023-04-13T15:51:08.5229817Z       /opt/hostedtoolcache/go/1.18.10/x64/src/testing/testing.go:1486 +0x47
2023-04-13T15:51:08.5229829Z 
2023-04-13T15:51:08.5229946Z Goroutine 79 (running) created at:
2023-04-13T15:51:08.5230287Z   github.com/nspcc-dev/neo-go/pkg/network.TestServerStartAndShutdown.func1()
2023-04-13T15:51:08.5230667Z       /home/runner/work/neo-go/neo-go/pkg/network/server_test.go:94 +0xf1
2023-04-13T15:51:08.5230771Z   testing.tRunner()
2023-04-13T15:51:08.5231076Z       /opt/hostedtoolcache/go/1.18.10/x64/src/testing/testing.go:1439 +0x213
2023-04-13T15:51:08.5231189Z   testing.(*T).Run.func1()
2023-04-13T15:51:08.5231527Z       /opt/hostedtoolcache/go/1.18.10/x64/src/testing/testing.go:1486 +0x47
2023-04-13T15:51:08.5231575Z 
2023-04-13T15:51:08.5231695Z Goroutine 42 (finished) created at:
2023-04-13T15:51:08.5231797Z   testing.(*T).Run()
2023-04-13T15:51:08.5232087Z       /opt/hostedtoolcache/go/1.18.10/x64/src/testing/testing.go:1486 +0x724
2023-04-13T15:51:08.5232200Z   testing.runTests.func1()
2023-04-13T15:51:08.5232496Z       /opt/hostedtoolcache/go/1.18.10/x64/src/testing/testing.go:1839 +0x99
2023-04-13T15:51:08.5232601Z   testing.tRunner()
2023-04-13T15:51:08.5232891Z       /opt/hostedtoolcache/go/1.18.10/x64/src/testing/testing.go:1439 +0x213
2023-04-13T15:51:08.5232994Z   testing.runTests()
2023-04-13T15:51:08.5233290Z       /opt/hostedtoolcache/go/1.18.10/x64/src/testing/testing.go:1837 +0x7e4
2023-04-13T15:51:08.5233389Z   testing.(*M).Run()
2023-04-13T15:51:08.5233673Z       /opt/hostedtoolcache/go/1.18.10/x64/src/testing/testing.go:1719 +0xa71
2023-04-13T15:51:08.5233765Z   main.main()
2023-04-13T15:51:08.5233930Z       _testmain.go:139 +0x2e4
2023-04-13T15:51:08.5234016Z ==================
2023-04-13T15:51:08.5234526Z     logger.go:130: 2023-04-13T15:45:33.475Z	INFO	started protocol	{"addr": "0.0.0.0:1", "userAgent": "fake", "startHeight": 0, "id": 0}
2023-04-13T15:51:08.5235092Z     logger.go:130: 2023-04-13T15:45:33.475Z	INFO	new peer connected	{"addr": "0.0.0.0:2", "peerCount": 2}
2023-04-13T15:51:08.5235592Z     logger.go:130: 2023-04-13T15:45:33.475Z	INFO	started protocol	{"addr": "0.0.0.0:2", "userAgent": "fake", "startHeight": 0, "id": 1}
2023-04-13T15:51:08.5236062Z     logger.go:130: 2023-04-13T15:45:33.491Z	INFO	new peer connected	{"addr": "0.0.0.0:3", "peerCount": 3}
2023-04-13T15:51:08.5236177Z peer dropped: max peers reached
2023-04-13T15:51:08.5236661Z     logger.go:130: 2023-04-13T15:45:33.491Z	WARN	peer disconnected	{"addr": "0.0.0.0:2", "error": "max peers reached", "peerCount": 2}
2023-04-13T15:51:08.5237212Z     logger.go:130: 2023-04-13T15:45:33.599Z	WARN	peer disconnected	{"addr": "0.0.0.0:3", "error": "identical node id", "peerCount": 1}
2023-04-13T15:51:08.5237575Z     logger.go:130: 2023-04-13T15:45:33.649Z	INFO	shutting down server	{"peers": 1}
2023-04-13T15:51:08.5237692Z peer dropped: server shutdown
2023-04-13T15:51:08.5237927Z     testing.go:1312: race detected during execution of test
2023-04-13T15:51:08.5238128Z --- FAIL: TestServerRegisterPeer (0.20s)
@AnnaShaleva AnnaShaleva added bug Something isn't working test Unit tests labels Apr 14, 2023
@AnnaShaleva AnnaShaleva added this to the v0.102.1 milestone Apr 14, 2023
@AnnaShaleva
Copy link
Member Author

AnnaShaleva commented Apr 14, 2023 •
edited
Loading

On Ubuntu (go 1.18), firstly discovered during #2969 test runs.

@roman-khimov roman-khimov modified the milestones: v0.103.0, v0.104.0 Oct 20, 2023
@AnnaShaleva AnnaShaleva modified the milestones: v0.104.0, v0.105.0 Nov 9, 2023
@roman-khimov roman-khimov added U2 Seriously planned S4 Routine I4 No visible changes labels Dec 21, 2023
@AnnaShaleva AnnaShaleva modified the milestones: v0.105.0, v0.106.0 Dec 28, 2023
AliceInHunterland added a commit that referenced this issue Feb 8, 2024
@AliceInHunterland
test: fix TestServerRegisterPeer data race
2dee68e 
To prevent writing to logs after the end of the test execution
concurrent registration and handshakes put to separate goroutines. To
prevent
 "closed twice" used shutdownOnce to ensure that the shutdown procedure
 is executed only once.

Close #2973

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
@AliceInHunterland AliceInHunterland mentioned this issue Feb 8, 2024
Merged
AliceInHunterland added a commit that referenced this issue Feb 9, 2024
@AliceInHunterland
network: fix TestServerRegisterPeer data race
924f0d5 
To prevent writing to logs after the end of the test execution
concurrent registration and handshakes put to separate goroutines.

Close #2973

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 13, 2024
@AliceInHunterland
network: fix TestServerRegisterPeer data race
ffd1e0b 
To prevent logs after the test ends we need to properly shutdown the
server. The problem is likely related to the fact that zap logger writes
 logs after the test ends.

 Close #2973

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 13, 2024
@AliceInHunterland
network: fix TestServerRegisterPeer data race
532a48d 
To prevent logs after the test ends we need to properly shutdown the
server. The problem is likely related to the fact that zap logger writes
 logs after the test ends.

 Close #2973

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 13, 2024
@AliceInHunterland
network: fix TestServerRegisterPeer data race
0dff702 
To prevent logs after the test ends we need to properly shutdown the
server. The problem is likely related to the fact that zap logger writes
 logs after the test ends.

 Close #2973

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 14, 2024
@AliceInHunterland
services: fix logs flush after services shutdown
8631889 
Added sync logs for every service separately to provide the ability to
have a custom logger for each service. Data race in logging is fixed by
adding a sync log, this problem is related to uber-go/zap#687.

 Close #2973
 Close #2974
 Close #3112
 Close #3217

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 14, 2024
@AliceInHunterland
services: fix logs flush after services shutdown
a52c5c4 
Added sync logs for every service separately to provide the ability to
have a custom logger for each service. Data race in logging is fixed by
adding a sync log, this problem is related to uber-go/zap#687.

 Close #2973
 Close #2974
 Close #3112
 Close #3217

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 14, 2024
@AliceInHunterland
services: fix logs flush after services shutdown
92174fb 
Added sync logs for every service separately to provide the ability to
have a custom logger for each service. Data race in logging is fixed by
adding a sync log, this problem is related to uber-go/zap#687.

 Close #2973
 Close #2974
 Close #3112
 Close #3217

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 14, 2024
@AliceInHunterland
services: fix logs flush after services shutdown
72fc814 
Added sync logs for every service separately to provide the ability to
have a custom logger for each service. Data race in logging is fixed by
adding a sync log, this problem is related to uber-go/zap#687.

 Close #2973
 Close #2974
 Close #3112
 Close #3217

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 14, 2024
@AliceInHunterland
services: fix logs flush after services shutdown
88140c5 
Added sync logs for every service separately to provide the ability to
have a custom logger for each service. Data race in logging is fixed by
adding a sync log, this problem is related to uber-go/zap#687.

 Close #2973
 Close #2974
 Close #3112
 Close #3217

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 15, 2024
@AliceInHunterland
services: fix logs flush after services shutdown
1cecb11 
Added sync logs for every service separately to provide the ability to
have a custom logger for each service. Data race in logging is fixed by
adding a sync log, this problem is related to uber-go/zap#687.

 Close #2973
 Close #2974
 Close #3112

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 15, 2024
@AliceInHunterland
services: fix logs flush after services shutdown
ea23772 
Added sync logs for every service separately to provide the ability to
have a custom logger for each service. Data race in logging is fixed by
adding a sync log, this problem is related to uber-go/zap#687.

 Close #2973
 Close #2974
 Close #3112

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 18, 2024
@AliceInHunterland
network: fix server shutdown by waiting for goroutines to finish
e765470 
s.Shutdown() does not wait for all goroutines of the node server to
finish normally just because the server exits without dependent
goroutines awaiting. Which causes logs to attempt to write after the
test has ended. The consequence of this bug fix is that corresponding
tests are fixed.

Close #2973
Close #2974

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 18, 2024
@AliceInHunterland
network: fix server shutdown by waiting for goroutines to finish
094de7d 
s.Shutdown() does not wait for all goroutines of the node server to
finish normally just because the server exits without dependent
goroutines awaiting. Which causes logs to attempt to write after the
test has ended. The consequence of this bug fix is that corresponding
tests are fixed.

Close #2973
Close #2974

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 18, 2024
@AliceInHunterland
network: fix server shutdown by waiting for goroutines to finish
c54395c 
s.Shutdown() does not wait for all goroutines of the node server to
finish normally just because the server exits without dependent
goroutines awaiting. Which causes logs to attempt to write after the
test has ended. The consequence of this bug fix is that corresponding
tests are fixed.

Close #2973
Close #2974

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 18, 2024
@AliceInHunterland
network: fix server shutdown by waiting for goroutines to finish
63b8c62 
s.Shutdown() does not wait for all goroutines of the node server to
finish normally just because the server exits without dependent
goroutines awaiting. Which causes logs to attempt to write after the
test has ended. The consequence of this bug fix is that corresponding
tests are fixed.

Close #2973
Close #2974

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 20, 2024
@AliceInHunterland
network: fix server shutdown by waiting for goroutines to finish
481bfff 
s.Shutdown() does not wait for all goroutines of the node server to
finish normally just because the server exits without dependent
goroutines awaiting. Which causes logs to attempt to write after the
test has ended. The consequence of this bug fix is that corresponding
tests are fixed.

Close #2973
Close #2974

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 20, 2024
@AliceInHunterland
network: fix server shutdown by waiting for goroutines to finish
7f0872c 
s.Shutdown() does not wait for all goroutines of the node server to
finish normally just because the server exits without dependent
goroutines awaiting. Which causes logs to attempt to write after the
test has ended. The consequence of this bug fix is that corresponding
tests are fixed.

Close #2973
Close #2974

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 20, 2024
@AliceInHunterland
network: fix server shutdown by waiting for goroutines to finish
63ddac4 
s.Shutdown() does not wait for all goroutines of the node server to
finish normally just because the server exits without dependent
goroutines awaiting. Which causes logs to attempt to write after the
test has ended. The consequence of this bug fix is that corresponding
tests are fixed.

Close #2973
Close #2974

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 20, 2024
@AliceInHunterland
network: fix server shutdown by waiting for goroutines to finish
bd3785c 
s.Shutdown() does not wait for all goroutines of the node server to
finish normally just because the server exits without dependent
goroutines awaiting. Which causes logs to attempt to write after the
test has ended. The consequence of this bug fix is that corresponding
tests are fixed.

Close #2973
Close #2974

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 21, 2024
@AliceInHunterland
network: fix server shutdown by waiting for goroutines to finish
749b841 
s.Shutdown() does not wait for all goroutines of the node server to
finish normally just because the server exits without dependent
goroutines awaiting. Which causes logs to attempt to write after the
test has ended. The consequence of this bug fix is that corresponding
tests are fixed.

Close #2973
Close #2974

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 21, 2024
@AliceInHunterland
network: fix server shutdown by waiting for goroutines to finish
9c788f2 
s.Shutdown() does not wait for all goroutines of the node server to
finish normally just because the server exits without dependent
goroutines awaiting. Which causes logs to attempt to write after the
test has ended. The consequence of this bug fix is that corresponding
tests are fixed.

Close #2973
Close #2974

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 21, 2024
@AliceInHunterland
network: fix server shutdown by waiting for goroutines to finish
211e354 
s.Shutdown() does not wait for all goroutines of the node server to
finish normally just because the server exits without dependent
goroutines awaiting. Which causes logs to attempt to write after the
test has ended. The consequence of this bug fix is that corresponding
tests are fixed.

Close #2973
Close #2974

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 21, 2024
@AliceInHunterland
network: fix server shutdown by waiting for goroutines to finish
04e6e21 
s.Shutdown() does not wait for all goroutines of the node server to
finish normally just because the server exits without dependent
goroutines awaiting. Which causes logs to attempt to write after the
test has ended. The consequence of this bug fix is that corresponding
tests are fixed.

Close #2973
Close #2974

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 21, 2024
@AliceInHunterland
network: fix server shutdown by waiting for goroutines to finish
f93304f 
s.Shutdown() does not wait for all goroutines of the node server to
finish normally just because the server exits without dependent
goroutines awaiting. Which causes logs to attempt to write after the
test has ended. The consequence of this bug fix is that corresponding
tests are fixed.

Close #2973
Close #2974

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 22, 2024
@AliceInHunterland
network: fix server shutdown by waiting for goroutines to finish
5e3b606 
s.Shutdown() does not wait for all goroutines of the node server to
finish normally just because the server exits without dependent
goroutines awaiting. Which causes logs to attempt to write after the
test has ended. The consequence of this bug fix is that corresponding
tests are fixed.

Close #2973
Close #2974

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 22, 2024
@AliceInHunterland
network: fix server shutdown by waiting for goroutines to finish
bbd6454 
s.Shutdown() does not wait for all goroutines of the node server to
finish normally just because the server exits without dependent
goroutines awaiting. Which causes logs to attempt to write after the
test has ended. The consequence of this bug fix is that corresponding
tests are fixed.

Close #2973
Close #2974

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AliceInHunterland added a commit that referenced this issue Feb 27, 2024
@AliceInHunterland
network: fix server shutdown by waiting for goroutines to finish
5cf0c75 
s.Shutdown() does not wait for all goroutines of the node server to
finish normally just because the server exits without dependent
goroutines awaiting. Which causes logs to attempt to write after the
test has ended. The consequence of this bug fix is that corresponding
tests are fixed.

Close #2973
Close #2974

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working I4 No visible changes S4 Routine test Unit tests U2 Seriously planned
Projects
None yet
Milestone
v0.106.0
Development

Successfully merging a pull request may close this issue.

services: fix logging data race after shutdown nspcc-dev/neo-go
2 participants
@roman-khimov @AnnaShaleva