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

Failing Windows subscriptions test #2956

Closed
AnnaShaleva opened this issue Mar 30, 2023 · 1 comment · Fixed by #3397
Closed

Failing Windows subscriptions test #2956

AnnaShaleva opened this issue Mar 30, 2023 · 1 comment · Fixed by #3397
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

Not sure whether it's a bug, but these tests were OK several days ago and it's better to be fixed.

2023-03-29T03:43:39.5184041Z === CONT  TestWSClient_SubscriptionsCompat/deprecated,_filtered
2023-03-29T03:43:39.5184199Z     client_test.go:2415: 
2023-03-29T03:43:39.5185041Z         	Error Trace:	D:\a\neo-go\neo-go\pkg\services\rpcsrv\client_test.go:2415
2023-03-29T03:43:39.5186163Z         	            				D:\a\neo-go\neo-go\pkg\services\rpcsrv\client_test.go:2429
2023-03-29T03:43:39.5186465Z         	Error:      	Condition never satisfied
2023-03-29T03:43:39.5186880Z         	Test:       	TestWSClient_SubscriptionsCompat/deprecated,_filtered
2023-03-29T03:43:39.5187074Z === CONT  TestWSClient_SubscriptionsCompat
2023-03-29T03:43:39.5187659Z     logger.go:130: 2023-03-29T03:35:04.261Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[0]"}
2023-03-29T03:43:39.5188230Z     logger.go:130: 2023-03-29T03:35:04.749Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[1]"}
2023-03-29T03:43:39.5188792Z     logger.go:130: 2023-03-29T03:35:06.082Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[2]"}
2023-03-29T03:43:39.5189531Z     logger.go:130: 2023-03-29T03:35:06.901Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[3]"}
2023-03-29T03:43:39.5189904Z === RUN   TestWSClient_SubscriptionsCompat/deprecated,_non-filtered
2023-03-29T03:43:39.5191138Z === CONT  TestWSClient_SubscriptionsCompat
2023-03-29T03:43:39.5192054Z     logger.go:130: 2023-03-29T03:35:08.756Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2023-03-29T03:43:39.5192874Z     logger.go:130: 2023-03-29T03:35:09.764Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[transaction_added]"}
2023-03-29T03:43:39.5193572Z     logger.go:130: 2023-03-29T03:35:10.375Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[notification_from_execution]"}
2023-03-29T03:43:39.5194255Z     logger.go:130: 2023-03-29T03:35:11.777Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[transaction_executed]"}
2023-03-29T03:43:39.5195271Z     logger.go:130: 2023-03-29T03:35:12.677Z	DEBUG	done processing headers	{"headerIndex": 2, "blockHeight": 1, "took": "191.1356ms"}
2023-03-29T03:43:39.5196170Z     logger.go:130: 2023-03-29T03:35:13.306Z	INFO	persisted to disk	{"blocks": 1, "keys": 44, "headerHeight": 2, "blockHeight": 2, "took": "0s"}
2023-03-29T03:43:39.5196553Z === CONT  TestWSClient_SubscriptionsCompat/deprecated,_non-filtered
2023-03-29T03:43:39.5196702Z     client_test.go:2415: 
2023-03-29T03:43:39.5197295Z         	Error Trace:	D:\a\neo-go\neo-go\pkg\services\rpcsrv\client_test.go:2415
2023-03-29T03:43:39.5198347Z         	            				D:\a\neo-go\neo-go\pkg\services\rpcsrv\client_test.go:2432
2023-03-29T03:43:39.5198885Z         	Error:      	Condition never satisfied
2023-03-29T03:43:39.5199592Z         	Test:       	TestWSClient_SubscriptionsCompat/deprecated,_non-filtered
2023-03-29T03:43:39.5199788Z === CONT  TestWSClient_SubscriptionsCompat
2023-03-29T03:43:39.5200339Z     logger.go:130: 2023-03-29T03:35:13.916Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[0]"}
2023-03-29T03:43:39.5201070Z     logger.go:130: 2023-03-29T03:35:14.733Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[1]"}
2023-03-29T03:43:39.5202691Z     logger.go:130: 2023-03-29T03:35:15.820Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[2]"}
2023-03-29T03:43:39.5203349Z     logger.go:130: 2023-03-29T03:35:16.599Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[3]"}
2023-03-29T03:43:39.5203585Z === RUN   TestWSClient_SubscriptionsCompat/relevant,_filtered
2023-03-29T03:43:39.5203777Z === CONT  TestWSClient_SubscriptionsCompat
2023-03-29T03:43:39.5204706Z     logger.go:130: 2023-03-29T03:35:17.399Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added ]"}
2023-03-29T03:43:39.5205830Z     logger.go:130: 2023-03-29T03:35:18.213Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[transaction_added ]"}
2023-03-29T03:43:39.5206469Z     logger.go:130: 2023-03-29T03:35:19.051Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[notification_from_execution ]"}
2023-03-29T03:43:39.5207370Z     logger.go:130: 2023-03-29T03:35:20.250Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[transaction_executed ]"}
2023-03-29T03:43:39.5207992Z     logger.go:130: 2023-03-29T03:35:21.728Z	DEBUG	done processing headers	{"headerIndex": 3, "blockHeight": 2, "took": "626.7157ms"}
2023-03-29T03:43:39.5208825Z     logger.go:130: 2023-03-29T03:35:22.535Z	INFO	persisted to disk	{"blocks": 1, "keys": 33, "headerHeight": 3, "blockHeight": 3, "took": "511µs"}
2023-03-29T03:43:39.5209225Z === CONT  TestWSClient_SubscriptionsCompat/relevant,_filtered
2023-03-29T03:43:39.5209624Z     client_test.go:2512: 
2023-03-29T03:43:39.5210322Z         	Error Trace:	D:\a\neo-go\neo-go\pkg\services\rpcsrv\client_test.go:2512
2023-03-29T03:43:39.5211192Z         	            				D:\a\neo-go\neo-go\pkg\services\rpcsrv\client_test.go:2526
2023-03-29T03:43:39.5211469Z         	Error:      	Condition never satisfied
2023-03-29T03:43:39.5211848Z         	Test:       	TestWSClient_SubscriptionsCompat/relevant,_filtered
2023-03-29T03:43:39.5212029Z === CONT  TestWSClient_SubscriptionsCompat
2023-03-29T03:43:39.5212689Z     logger.go:130: 2023-03-29T03:35:23.348Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[0]"}
2023-03-29T03:43:39.5213264Z     logger.go:130: 2023-03-29T03:35:24.480Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[1]"}
2023-03-29T03:43:39.5213776Z     logger.go:130: 2023-03-29T03:35:25.231Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[2]"}
2023-03-29T03:43:39.5214293Z     logger.go:130: 2023-03-29T03:35:26.374Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[3]"}
2023-03-29T03:43:39.5214633Z === RUN   TestWSClient_SubscriptionsCompat/relevant,_non-filtered
2023-03-29T03:43:39.5214956Z === CONT  TestWSClient_SubscriptionsCompat
2023-03-29T03:43:39.5215526Z     logger.go:130: 2023-03-29T03:35:27.368Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2023-03-29T03:43:39.5216093Z     logger.go:130: 2023-03-29T03:35:28.272Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[transaction_added]"}
2023-03-29T03:43:39.5216702Z     logger.go:130: 2023-03-29T03:35:29.094Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[notification_from_execution]"}
2023-03-29T03:43:39.5217281Z     logger.go:130: 2023-03-29T03:35:30.059Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[transaction_executed]"}
2023-03-29T03:43:39.5217834Z     logger.go:130: 2023-03-29T03:35:31.922Z	DEBUG	done processing headers	{"headerIndex": 4, "blockHeight": 3, "took": "0s"}
2023-03-29T03:43:39.5218361Z     logger.go:130: 2023-03-29T03:35:32.887Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[0]"}
2023-03-29T03:43:39.5218971Z     logger.go:130: 2023-03-29T03:35:32.947Z	INFO	persisted to disk	{"blocks": 1, "keys": 40, "headerHeight": 4, "blockHeight": 4, "took": "0s"}
2023-03-29T03:43:39.5219498Z     logger.go:130: 2023-03-29T03:35:33.287Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[1]"}
2023-03-29T03:43:39.5220126Z     logger.go:130: 2023-03-29T03:35:34.100Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[2]"}
2023-03-29T03:43:39.5220698Z     logger.go:130: 2023-03-29T03:35:35.291Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[3]"}
2023-03-29T03:43:39.5221197Z     logger.go:130: 2023-03-29T03:35:35.923Z	INFO	shutting down RPC server	{"endpoint": "127.0.0.1:51350"}
2023-03-29T03:43:39.5221439Z --- FAIL: TestWSClient_SubscriptionsCompat (46.85s)
2023-03-29T03:43:39.5222010Z     --- FAIL: TestWSClient_SubscriptionsCompat/deprecated,_filtered (13.74s)
2023-03-29T03:43:39.5222441Z     --- FAIL: TestWSClient_SubscriptionsCompat/deprecated,_non-filtered (8.69s)
2023-03-29T03:43:39.5222859Z     --- FAIL: TestWSClient_SubscriptionsCompat/relevant,_filtered (9.84s)
2023-03-29T03:43:39.5223279Z     --- PASS: TestWSClient_SubscriptionsCompat/relevant,_non-filtered (8.88s)
@AnnaShaleva AnnaShaleva added the test Unit tests label Mar 30, 2023
@AnnaShaleva AnnaShaleva added the bug Something isn't working label Apr 6, 2023
@AnnaShaleva AnnaShaleva added this to the v0.102.1 milestone Apr 6, 2023
@roman-khimov roman-khimov modified the milestones: v0.103.0, v0.104.0 Oct 19, 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 Mar 5, 2024
@AliceInHunterland
rpcsrv: add close of http server in tests
4f9a098 
The HTTP server should be closed at the end of the test to prevent fd
leak.

Refs #3300
Close #3312
Close #2956
Close #3005
Ref #2958

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
@AliceInHunterland AliceInHunterland mentioned this issue Mar 5, 2024
Merged
@AnnaShaleva
Copy link
Member Author

@AliceInHunterland, this issue is not related to #3340, it's a separate problem because here we start a full separate RPC server.

I had a thought that the reason for this test failure was connected with the fact that RPC server doesn't wait for the end of execution of SubscribeForBlocks, SubscribeForExecutions, ... blockchain's APIs calls, but it properly waits, so the reason is not in these calls as far.

AnnaShaleva added a commit that referenced this issue Mar 12, 2024
@AnnaShaleva
rpcsrv: improve TestWSClient_SubscriptionsCompat
65f56c8 
Close exit channel on exit, wait more for the test to finish.

Ref. #2956.

Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
@AliceInHunterland AliceInHunterland mentioned this issue Mar 27, 2024
Merged
AnnaShaleva added a commit that referenced this issue Apr 4, 2024
@AnnaShaleva
rpcsrv: allow one-block slippage in TestWSClient_SubscriptionsCompat
90c9fa4 
Close #2956. The failure reason is similar to the one described in #3396
for TestNotary: Blockchain's notificationDispatcher is listening to
block events from storeBlock via separate channel. By the moment single
block addition is finished, notification may or may not be properly
handled by notificationDispatcher, especially given the fact that our
runners are slow. As a result, assert.Eventually with 1-second awaiting
period may fail. This issue is solved by adding one more block, because
the second AddBlock finishes only when it sends block addition event to
notificationDispatcher loop, which means that the previous event was
handled.

Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
@AnnaShaleva AnnaShaleva mentioned this issue Apr 4, 2024
Merged
AnnaShaleva added a commit that referenced this issue Apr 4, 2024
@AnnaShaleva
rpcsrv: allow one-block slippage in TestWSClient_SubscriptionsCompat
ef3ec19 
Close #2956. The failure reason is similar to the one described in #3396
for TestNotary: Blockchain's notificationDispatcher is listening to
block events from storeBlock via separate channel. By the moment single
block addition is finished, notification may or may not be properly
handled by notificationDispatcher, especially given the fact that our
runners are slow. As a result, assert.Eventually with 1-second awaiting
period may fail. This issue is solved by adding one more block, because
the second AddBlock finishes only when it sends block addition event to
notificationDispatcher loop, which means that the previous event was
handled.

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
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.

rpcsrv: allow one-block slippage in TestWSClient_SubscriptionsCompat nspcc-dev/neo-go
2 participants
@roman-khimov @AnnaShaleva