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.

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

TestServerStartAndShutdown fails #3399

Closed
AnnaShaleva opened this issue Apr 4, 2024 · 1 comment · Fixed by #3400
Closed

TestServerStartAndShutdown fails #3399

AnnaShaleva opened this issue Apr 4, 2024 · 1 comment · Fixed by #3400
Labels
bug Something isn't working I4 No visible changes S4 Routine test Unit tests U2 Seriously planned
Milestone

Comments

@AnnaShaleva
Copy link
Member

Go 1.22, MacOS, firstly discovered in #3398.

2024-04-04T09:47:28.5050930Z === RUN   TestServerStartAndShutdown
2024-04-04T09:47:28.5051200Z === RUN   TestServerStartAndShutdown/no_consensus
2024-04-04T09:47:28.5052500Z     logger.go:146: 2024-04-04T09:43:01.073Z	INFO	ExtensiblePoolSize is not set or wrong, using default value	{"ExtensiblePoolSize": 20}
2024-04-04T09:47:28.5053710Z     logger.go:146: 2024-04-04T09:43:01.073Z	INFO	bad MaxPeers configured, using the default value	{"configured": 0, "actual": 100}
2024-04-04T09:47:28.5055010Z     logger.go:146: 2024-04-04T09:43:01.073Z	INFO	bad AttemptConnPeers configured, using the default value	{"configured": 0, "actual": 20}
2024-04-04T09:47:28.5055960Z     logger.go:146: 2024-04-04T09:43:01.073Z	INFO	node started	{"blockHeight": 0, "headerHeight": 0}
2024-04-04T09:47:28.5056860Z     logger.go:146: 2024-04-04T09:43:01.073Z	INFO	node reached synchronized state, starting services
2024-04-04T09:47:28.5057800Z     logger.go:146: 2024-04-04T09:43:01.074Z	INFO	new peer connected	{"addr": "0.0.0.0:0", "peerCount": 1}
2024-04-04T09:47:28.5058020Z     server_test.go:98: 
2024-04-04T09:47:28.5058830Z         	Error Trace:	/Users/runner/work/neo-go/neo-go/pkg/network/server_test.go:98
2024-04-04T09:47:28.5059170Z         	Error:      	Should be true
2024-04-04T09:47:28.5059600Z         	Test:       	TestServerStartAndShutdown/no_consensus
2024-04-04T09:47:28.5060310Z     logger.go:146: 2024-04-04T09:43:01.084Z	INFO	shutting down server	{"peers": 1}
2024-04-04T09:47:28.5060510Z peer dropped: server shutdown
2024-04-04T09:47:28.5061700Z     logger.go:146: 2024-04-04T09:43:01.088Z	WARN	peer disconnected	{"addr": "0.0.0.0:0", "error": "server shutdown", "peerCount": 0}
2024-04-04T09:47:28.5062070Z === RUN   TestServerStartAndShutdown/with_consensus
2024-04-04T09:47:28.5063380Z     logger.go:146: 2024-04-04T09:43:01.088Z	INFO	ExtensiblePoolSize is not set or wrong, using default value	{"ExtensiblePoolSize": 20}
2024-04-04T09:47:28.5064680Z     logger.go:146: 2024-04-04T09:43:01.088Z	INFO	bad MaxPeers configured, using the default value	{"configured": 0, "actual": 100}
2024-04-04T09:47:28.5065990Z     logger.go:146: 2024-04-04T09:43:01.088Z	INFO	bad AttemptConnPeers configured, using the default value	{"configured": 0, "actual": 20}
2024-04-04T09:47:28.5066880Z     logger.go:146: 2024-04-04T09:43:01.088Z	INFO	node started	{"blockHeight": 0, "headerHeight": 0}
2024-04-04T09:47:28.5067760Z     logger.go:146: 2024-04-04T09:43:01.088Z	INFO	node reached synchronized state, starting services
2024-04-04T09:47:28.5068680Z     logger.go:146: 2024-04-04T09:43:01.088Z	INFO	new peer connected	{"addr": "0.0.0.0:0", "peerCount": 1}
2024-04-04T09:47:28.5069380Z     logger.go:146: 2024-04-04T09:43:01.088Z	INFO	shutting down server	{"peers": 1}
2024-04-04T09:47:28.5069580Z peer dropped: server shutdown
2024-04-04T09:47:28.5070780Z     logger.go:146: 2024-04-04T09:43:01.089Z	WARN	peer disconnected	{"addr": "0.0.0.0:0", "error": "server shutdown", "peerCount": 0}
2024-04-04T09:47:28.5071050Z === RUN   TestServerStartAndShutdown/double_start
2024-04-04T09:47:28.5072330Z     logger.go:146: 2024-04-04T09:43:01.089Z	INFO	ExtensiblePoolSize is not set or wrong, using default value	{"ExtensiblePoolSize": 20}
2024-04-04T09:47:28.5073550Z     logger.go:146: 2024-04-04T09:43:01.089Z	INFO	bad MaxPeers configured, using the default value	{"configured": 0, "actual": 100}
2024-04-04T09:47:28.5074850Z     logger.go:146: 2024-04-04T09:43:01.089Z	INFO	bad AttemptConnPeers configured, using the default value	{"configured": 0, "actual": 20}
2024-04-04T09:47:28.5075730Z     logger.go:146: 2024-04-04T09:43:01.089Z	INFO	node started	{"blockHeight": 0, "headerHeight": 0}
2024-04-04T09:47:28.5076600Z     logger.go:146: 2024-04-04T09:43:01.089Z	INFO	node reached synchronized state, starting services
2024-04-04T09:47:28.5077230Z     logger.go:146: 2024-04-04T09:43:01.089Z	INFO	node server already started
2024-04-04T09:47:28.5077930Z     logger.go:146: 2024-04-04T09:43:01.089Z	INFO	shutting down server	{"peers": 0}
2024-04-04T09:47:28.5078230Z === RUN   TestServerStartAndShutdown/double_shutdown
2024-04-04T09:47:28.5079520Z     logger.go:146: 2024-04-04T09:43:01.089Z	INFO	ExtensiblePoolSize is not set or wrong, using default value	{"ExtensiblePoolSize": 20}
2024-04-04T09:47:28.5080740Z     logger.go:146: 2024-04-04T09:43:01.090Z	INFO	bad MaxPeers configured, using the default value	{"configured": 0, "actual": 100}
2024-04-04T09:47:28.5082030Z     logger.go:146: 2024-04-04T09:43:01.090Z	INFO	bad AttemptConnPeers configured, using the default value	{"configured": 0, "actual": 20}
2024-04-04T09:47:28.5082900Z     logger.go:146: 2024-04-04T09:43:01.090Z	INFO	node started	{"blockHeight": 0, "headerHeight": 0}
2024-04-04T09:47:28.5083840Z     logger.go:146: 2024-04-04T09:43:01.090Z	INFO	node reached synchronized state, starting services
2024-04-04T09:47:28.5084560Z     logger.go:146: 2024-04-04T09:43:01.090Z	INFO	shutting down server	{"peers": 0}
2024-04-04T09:47:28.5084880Z --- FAIL: TestServerStartAndShutdown (0.02s)
2024-04-04T09:47:28.5085350Z     --- FAIL: TestServerStartAndShutdown/no_consensus (0.02s)
2024-04-04T09:47:28.5085850Z     --- PASS: TestServerStartAndShutdown/with_consensus (0.00s)
2024-04-04T09:47:28.5086400Z     --- PASS: TestServerStartAndShutdown/double_start (0.00s)
2024-04-04T09:47:28.5086910Z     --- PASS: TestServerStartAndShutdown/double_shutdown (0.00s)
@AnnaShaleva AnnaShaleva added bug Something isn't working U2 Seriously planned test Unit tests S4 Routine I4 No visible changes labels Apr 4, 2024
@AnnaShaleva AnnaShaleva added this to the v0.106.0 milestone Apr 4, 2024
@roman-khimov
Copy link
Member

I'm so used to RPC test problems that seeing something in pkg/network is actually surprising.

AnnaShaleva added a commit that referenced this issue Apr 4, 2024
We don't have a reliable way to know when transports are started since
their start is being performed in a separate goroutine:

https://github.com/nspcc-dev/neo-go/blob/927dbb6dc48d578ae731e5a067c82d0611642338/pkg/network/server.go#L297-L299

And transports start is not connected with main server routine, thus,
just wait for some time for the transports goroutine to be started.

Close #3399.

Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
AnnaShaleva added a commit that referenced this issue Apr 4, 2024
We don't have a reliable way to know when transports are started since
their start is being performed in a separate goroutine:

https://github.com/nspcc-dev/neo-go/blob/927dbb6dc48d578ae731e5a067c82d0611642338/pkg/network/server.go#L297-L299

And transports start is not connected with main server routine, thus,
just wait for some time for the transports goroutine to be started.

Also wait for the peer to be properly registered.

Close #3399.

Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working I4 No visible changes S4 Routine test Unit tests U2 Seriously planned
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants