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

WS-based RPC server tests fail on Windows #3378

Closed
AnnaShaleva opened this issue Mar 27, 2024 · 5 comments · Fixed by #3387, #3392 or #3398
Closed

WS-based RPC server tests fail on Windows #3378

AnnaShaleva opened this issue Mar 27, 2024 · 5 comments · Fixed by #3387, #3392 or #3398
Assignees
@AnnaShaleva
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

Go 1.22, Windows, e10c584. The failure error read tcp 127.0.0.1:59625->127.0.0.1:59624: i/o timeout looks exactly like in the previously failing TestRPC (#3314). To solve it we should try the same approach as the one used in #3368.

2024-03-27T13:28:35.7306245Z === NAME  TestFilteredNotaryRequestSubscriptions
2024-03-27T13:28:35.7306897Z     logger.go:146: 2024-03-27T13:23:17.951Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[notary_request_event ]"}
2024-03-27T13:28:35.7307032Z     subscription_test.go:36: 
2024-03-27T13:28:35.7307520Z         	Error Trace:	D:/a/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:36
2024-03-27T13:28:35.7308127Z         	            				C:/hostedtoolcache/windows/go/1.22.1/x64/src/runtime/asm_amd64.s:1695
2024-03-27T13:28:35.7308336Z         	Error:      	Received unexpected error:
2024-03-27T13:28:35.7308816Z         	            	read tcp 127.0.0.1:59625->127.0.0.1:59624: i/o timeout
2024-03-27T13:28:35.7309122Z         	Test:       	TestFilteredNotaryRequestSubscriptions
2024-03-27T13:28:35.7309869Z     logger.go:146: 2024-03-27T13:23:18.541Z	INFO	persisted to disk	{"blocks": 8, "keys": 771, "headerHeight": 23, "blockHeight": 23, "took": "0s"}
2024-03-27T13:28:35.7309979Z panic: test timed out after 15m0s
2024-03-27T13:28:35.7310066Z running tests:
2024-03-27T13:28:35.7310240Z 	TestFilteredNotaryRequestSubscriptions (3m7s)
2024-03-27T13:28:35.7310485Z 	TestFilteredNotaryRequestSubscriptions/matching_signer (3m6s)
2024-03-27T13:28:35.7310492Z 
2024-03-27T13:28:35.7310583Z goroutine 14131 [running]:
2024-03-27T13:28:35.7310683Z testing.(*M).startAlarm.func1()
2024-03-27T13:28:35.7310968Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:2366 +0x265
2024-03-27T13:28:35.7311057Z created by time.goFunc
2024-03-27T13:28:35.7311317Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/time/sleep.go:177 +0x45
2024-03-27T13:28:35.7311323Z 
2024-03-27T13:28:35.7311438Z goroutine 1 [chan receive, 3 minutes]:
2024-03-27T13:28:35.7311631Z testing.(*T).Run(0xc0002d6680, {0x141581c75, 0x26}, 0x141687388)
2024-03-27T13:28:35.7311943Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:1750 +0x851
2024-03-27T13:28:35.7312087Z testing.runTests.func1(0xc0002d6680)
2024-03-27T13:28:35.7312370Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:2161 +0x86
2024-03-27T13:28:35.7312493Z testing.tRunner(0xc0002d6680, 0xc000217b10)
2024-03-27T13:28:35.7312773Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:1689 +0x21f
2024-03-27T13:28:35.7313119Z testing.runTests(0xc0002f0be8, {0x1412d57e0, 0x31, 0x31}, {0xc000217bb8?, 0xc000217c00?, 0x1421220e0?})
2024-03-27T13:28:35.7313391Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:2159 +0x8bf
2024-03-27T13:28:35.7313486Z testing.(*M).Run(0xc0002834a0)
2024-03-27T13:28:35.7313747Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:2027 +0xf18
2024-03-27T13:28:35.7313829Z main.main()
2024-03-27T13:28:35.7313935Z 	_testmain.go:145 +0x2be
2024-03-27T13:28:35.7313942Z 
2024-03-27T13:28:35.7314070Z goroutine 14148 [chan receive, 3 minutes]:
2024-03-27T13:28:35.7314394Z github.com/nspcc-dev/neo-go/pkg/network/bqueue.(*Queue).Run(0xc00051d500)
2024-03-27T13:28:35.7314638Z 	D:/a/neo-go/neo-go/pkg/network/bqueue/queue.go:60 +0x9b
2024-03-27T13:28:35.7315006Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 14116
2024-03-27T13:28:35.7315222Z 	D:/a/neo-go/neo-go/pkg/network/server.go:296 +0x605
2024-03-27T13:28:35.7315233Z 
2024-03-27T13:28:35.7315324Z goroutine 4997 [runnable]:
2024-03-27T13:28:35.7315430Z sync/atomic.(*Value).Load(0xc0006e52d8)
2024-03-27T13:28:35.7315706Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/sync/atomic/value.go:28 +0xf9
2024-03-27T13:28:35.7315812Z context.(*cancelCtx).Done(0xc0006e52c0)
2024-03-27T13:28:35.7316081Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/context/context.go:439 +0x50
2024-03-27T13:28:35.7316419Z github.com/nspcc-dev/neo-go/pkg/rpcclient.(*Internal).eventLoop(0xc000f6cc40)
2024-03-27T13:28:35.7316635Z 	D:/a/neo-go/neo-go/pkg/rpcclient/local.go:55 +0x73
2024-03-27T13:28:35.7316993Z created by github.com/nspcc-dev/neo-go/pkg/rpcclient.NewInternal in goroutine 4959
2024-03-27T13:28:35.7317204Z 	D:/a/neo-go/neo-go/pkg/rpcclient/local.go:45 +0x3cd
2024-03-27T13:28:35.7317209Z 
2024-03-27T13:28:35.7317302Z goroutine 14154 [select]:
2024-03-27T13:28:35.7317604Z github.com/nspcc-dev/neo-go/pkg/network.(*Server).runProto(0xc0001ebc08)
2024-03-27T13:28:35.7317817Z 	D:/a/neo-go/neo-go/pkg/network/server.go:553 +0x229
2024-03-27T13:28:35.7318169Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).run in goroutine 14150
2024-03-27T13:28:35.7318374Z 	D:/a/neo-go/neo-go/pkg/network/server.go:453 +0x295
2024-03-27T13:28:35.7318379Z 
2024-03-27T13:28:35.7318480Z goroutine 14127 [select, 3 minutes]:
2024-03-27T13:28:35.7318804Z github.com/nspcc-dev/neo-go/pkg/network.(*Server).txHandlerLoop(0xc0001ebc08)
2024-03-27T13:28:35.7319062Z 	D:/a/neo-go/neo-go/pkg/network/server.go:1155 +0x23c
2024-03-27T13:28:35.7319504Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 14116
2024-03-27T13:28:35.7319717Z 	D:/a/neo-go/neo-go/pkg/network/server.go:291 +0x31c
2024-03-27T13:28:35.7319723Z 
2024-03-27T13:28:35.7319822Z goroutine 14128 [select, 3 minutes]:
2024-03-27T13:28:35.7320151Z github.com/nspcc-dev/neo-go/pkg/network.(*Server).txHandlerLoop(0xc0001ebc08)
2024-03-27T13:28:35.7320364Z 	D:/a/neo-go/neo-go/pkg/network/server.go:1155 +0x23c
2024-03-27T13:28:35.7320718Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 14116
2024-03-27T13:28:35.7320926Z 	D:/a/neo-go/neo-go/pkg/network/server.go:291 +0x31c
2024-03-27T13:28:35.7320931Z 
2024-03-27T13:28:35.7321018Z goroutine 14118 [select]:
2024-03-27T13:28:35.7321307Z github.com/nspcc-dev/neo-go/pkg/core.(*Blockchain).Run(0xc000315208)
2024-03-27T13:28:35.7321529Z 	D:/a/neo-go/neo-go/pkg/core/blockchain.go:1074 +0x2dc
2024-03-27T13:28:35.7322102Z created by github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.getUnitTestChainWithCustomConfig in goroutine 14116
2024-03-27T13:28:35.7322453Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/server_helper_test.go:85 +0x737
2024-03-27T13:28:35.7322459Z 
2024-03-27T13:28:35.7322552Z goroutine 5019 [runnable]:
2024-03-27T13:28:35.7323027Z github.com/nspcc-dev/neo-go/pkg/rpcclient.(*WSClient).notifySubscribers(0xc000f6ce00, {0x0?, {0x0?, 0x0?}})
2024-03-27T13:28:35.7323260Z 	D:/a/neo-go/neo-go/pkg/rpcclient/wsclient.go:683 +0x629
2024-03-27T13:28:35.7323594Z github.com/nspcc-dev/neo-go/pkg/rpcclient.(*Internal).eventLoop(0xc000f6ce00)
2024-03-27T13:28:35.7323800Z 	D:/a/neo-go/neo-go/pkg/rpcclient/local.go:64 +0x47
2024-03-27T13:28:35.7324162Z created by github.com/nspcc-dev/neo-go/pkg/rpcclient.NewInternal in goroutine 5013
2024-03-27T13:28:35.7324711Z 	D:/a/neo-go/neo-go/pkg/rpcclient/local.go:45 +0x3cd
2024-03-27T13:28:35.7324719Z 
2024-03-27T13:28:35.7324841Z goroutine 14120 [IO wait, 3 minutes]:
2024-03-27T13:28:35.7324996Z internal/poll.runtime_pollWait(0x48719fd8, 0x72)
2024-03-27T13:28:35.7325270Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/runtime/netpoll.go:345 +0x85
2024-03-27T13:28:35.7325444Z internal/poll.(*pollDesc).wait(0xc001b030c0, 0x72, 0x0)
2024-03-27T13:28:35.7325780Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_poll_runtime.go:84 +0xb1
2024-03-27T13:28:35.7325923Z internal/poll.execIO(0xc001b02f20, 0xc000059930)
2024-03-27T13:28:35.7326236Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:175 +0x271
2024-03-27T13:28:35.7326539Z internal/poll.(*FD).acceptOne(0xc001b02f08, 0x494, {0xc000925680, 0x2, 0x2}, 0xc001b02f20)
2024-03-27T13:28:35.7326850Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:944 +0xf8
2024-03-27T13:28:35.7327013Z internal/poll.(*FD).Accept(0xc001b02f08, 0xc001007ba8)
2024-03-27T13:28:35.7327326Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:978 +0x3cb
2024-03-27T13:28:35.7327429Z net.(*netFD).accept(0xc001b02f08)
2024-03-27T13:28:35.7327698Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/fd_windows.go:178 +0x85
2024-03-27T13:28:35.7327810Z net.(*TCPListener).accept(0xc003bc4400)
2024-03-27T13:28:35.7328089Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/tcpsock_posix.go:159 +0x3e
2024-03-27T13:28:35.7328198Z net.(*TCPListener).Accept(0xc003bc4400)
2024-03-27T13:28:35.7328445Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/tcpsock.go:327 +0x65
2024-03-27T13:28:35.7328654Z net/http.(*Server).Serve(0xc000c5ca50, {0x141869d20, 0xc003bc4400})
2024-03-27T13:28:35.7328919Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/http/server.go:3255 +0x672
2024-03-27T13:28:35.7329301Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).Start.func1(0xc000c5ca50)
2024-03-27T13:28:35.7329552Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/server.go:403 +0x79
2024-03-27T13:28:35.7330035Z created by github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).Start in goroutine 14116
2024-03-27T13:28:35.7330326Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/server.go:402 +0x1c5
2024-03-27T13:28:35.7330334Z 
2024-03-27T13:28:35.7330443Z goroutine 14122 [select, 3 minutes]:
2024-03-27T13:28:35.7330820Z github.com/nspcc-dev/neo-go/pkg/core.(*Blockchain).notificationDispatcher(0xc000315208)
2024-03-27T13:28:35.7331043Z 	D:/a/neo-go/neo-go/pkg/core/blockchain.go:1336 +0x4b6
2024-03-27T13:28:35.7331411Z created by github.com/nspcc-dev/neo-go/pkg/core.(*Blockchain).Run in goroutine 14118
2024-03-27T13:28:35.7331626Z 	D:/a/neo-go/neo-go/pkg/core/blockchain.go:1071 +0x18b
2024-03-27T13:28:35.7331632Z 
2024-03-27T13:28:35.7331737Z goroutine 14126 [select, 3 minutes]:
2024-03-27T13:28:35.7332069Z github.com/nspcc-dev/neo-go/pkg/network.(*Server).txHandlerLoop(0xc0001ebc08)
2024-03-27T13:28:35.7332286Z 	D:/a/neo-go/neo-go/pkg/network/server.go:1155 +0x23c
2024-03-27T13:28:35.7332648Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 14116
2024-03-27T13:28:35.7332860Z 	D:/a/neo-go/neo-go/pkg/network/server.go:291 +0x31c
2024-03-27T13:28:35.7332870Z 
2024-03-27T13:28:35.7333007Z goroutine 14146 [select, 3 minutes]:
2024-03-27T13:28:35.7333377Z github.com/nspcc-dev/neo-go/pkg/network.(*Server).relayBlocksLoop(0xc0001ebc08)
2024-03-27T13:28:35.7333595Z 	D:/a/neo-go/neo-go/pkg/network/server.go:1589 +0x225
2024-03-27T13:28:35.7333956Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 14116
2024-03-27T13:28:35.7334170Z 	D:/a/neo-go/neo-go/pkg/network/server.go:294 +0x4ab
2024-03-27T13:28:35.7334175Z 
2024-03-27T13:28:35.7334287Z goroutine 14149 [IO wait, 3 minutes]:
2024-03-27T13:28:35.7334431Z internal/poll.runtime_pollWait(0x48798080, 0x72)
2024-03-27T13:28:35.7334700Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/runtime/netpoll.go:345 +0x85
2024-03-27T13:28:35.7334867Z internal/poll.(*pollDesc).wait(0xc001b03ac0, 0x72, 0x0)
2024-03-27T13:28:35.7335205Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_poll_runtime.go:84 +0xb1
2024-03-27T13:28:35.7335344Z internal/poll.execIO(0xc001b03920, 0xc0003e59e0)
2024-03-27T13:28:35.7335660Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:175 +0x271
2024-03-27T13:28:35.7335959Z internal/poll.(*FD).acceptOne(0xc001b03908, 0x2a0, {0xc000925770, 0x2, 0x2}, 0xc001b03920)
2024-03-27T13:28:35.7336274Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:944 +0xf8
2024-03-27T13:28:35.7336434Z internal/poll.(*FD).Accept(0xc001b03908, 0xc0005e5c58)
2024-03-27T13:28:35.7336745Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:978 +0x3cb
2024-03-27T13:28:35.7336848Z net.(*netFD).accept(0xc001b03908)
2024-03-27T13:28:35.7337105Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/fd_windows.go:178 +0x85
2024-03-27T13:28:35.7337217Z net.(*TCPListener).accept(0xc003bc4680)
2024-03-27T13:28:35.7337491Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/tcpsock_posix.go:159 +0x3e
2024-03-27T13:28:35.7337604Z net.(*TCPListener).Accept(0xc003bc4680)
2024-03-27T13:28:35.7337848Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/tcpsock.go:327 +0x65
2024-03-27T13:28:35.7338181Z github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Accept(0xc0014844d0)
2024-03-27T13:28:35.7338430Z 	D:/a/neo-go/neo-go/pkg/network/tcp_transport.go:78 +0x448
2024-03-27T13:28:35.7338793Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 14116
2024-03-27T13:28:35.7339005Z 	D:/a/neo-go/neo-go/pkg/network/server.go:298 +0x63d
2024-03-27T13:28:35.7339010Z 
2024-03-27T13:28:35.7339112Z goroutine 14125 [select, 3 minutes]:
2024-03-27T13:28:35.7339444Z github.com/nspcc-dev/neo-go/pkg/network.(*Server).txHandlerLoop(0xc0001ebc08)
2024-03-27T13:28:35.7339660Z 	D:/a/neo-go/neo-go/pkg/network/server.go:1155 +0x23c
2024-03-27T13:28:35.7340023Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 14116
2024-03-27T13:28:35.7340268Z 	D:/a/neo-go/neo-go/pkg/network/server.go:291 +0x31c
2024-03-27T13:28:35.7340304Z 
2024-03-27T13:28:35.7340405Z goroutine 14150 [select, 3 minutes]:
2024-03-27T13:28:35.7340690Z github.com/nspcc-dev/neo-go/pkg/network.(*Server).run(0xc0001ebc08)
2024-03-27T13:28:35.7340894Z 	D:/a/neo-go/neo-go/pkg/network/server.go:484 +0x919
2024-03-27T13:28:35.7341249Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 14116
2024-03-27T13:28:35.7341450Z 	D:/a/neo-go/neo-go/pkg/network/server.go:303 +0x874
2024-03-27T13:28:35.7341455Z 
2024-03-27T13:28:35.7341580Z goroutine 14147 [chan receive, 3 minutes]:
2024-03-27T13:28:35.7341885Z github.com/nspcc-dev/neo-go/pkg/network/bqueue.(*Queue).Run(0xc00051d480)
2024-03-27T13:28:35.7342114Z 	D:/a/neo-go/neo-go/pkg/network/bqueue/queue.go:60 +0x9b
2024-03-27T13:28:35.7342466Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 14116
2024-03-27T13:28:35.7342666Z 	D:/a/neo-go/neo-go/pkg/network/server.go:295 +0x557
2024-03-27T13:28:35.7342673Z 
2024-03-27T13:28:35.7342770Z goroutine 4714 [runnable]:
2024-03-27T13:28:35.7342877Z sync/atomic.(*Value).Load(0xc0007f4dd8)
2024-03-27T13:28:35.7343191Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/sync/atomic/value.go:36 +0x93
2024-03-27T13:28:35.7343330Z context.(*cancelCtx).Done(0xc0007f4dc0)
2024-03-27T13:28:35.7343598Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/context/context.go:439 +0x50
2024-03-27T13:28:35.7343932Z github.com/nspcc-dev/neo-go/pkg/rpcclient.(*Internal).eventLoop(0xc0007b3880)
2024-03-27T13:28:35.7344137Z 	D:/a/neo-go/neo-go/pkg/rpcclient/local.go:55 +0x73
2024-03-27T13:28:35.7344496Z created by github.com/nspcc-dev/neo-go/pkg/rpcclient.NewInternal in goroutine 4708
2024-03-27T13:28:35.7344699Z 	D:/a/neo-go/neo-go/pkg/rpcclient/local.go:45 +0x3cd
2024-03-27T13:28:35.7344704Z 
2024-03-27T13:28:35.7344828Z goroutine 14116 [chan receive, 3 minutes]:
2024-03-27T13:28:35.7345014Z testing.(*T).Run(0xc0002dba00, {0x141561446, 0xf}, 0xc0036ba900)
2024-03-27T13:28:35.7345290Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:1750 +0x851
2024-03-27T13:28:35.7345781Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.TestFilteredNotaryRequestSubscriptions(0xc0002dba00)
2024-03-27T13:28:35.7346098Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:403 +0x792
2024-03-27T13:28:35.7346219Z testing.tRunner(0xc0002dba00, 0x141687388)
2024-03-27T13:28:35.7346490Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:1689 +0x21f
2024-03-27T13:28:35.7346612Z created by testing.(*T).Run in goroutine 1
2024-03-27T13:28:35.7346871Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:1742 +0x826
2024-03-27T13:28:35.7346876Z 
2024-03-27T13:28:35.7346982Z goroutine 14119 [select, 3 minutes]:
2024-03-27T13:28:35.7347361Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).handleSubEvents(0xc001b02a08)
2024-03-27T13:28:35.7347617Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/server.go:2920 +0x86d
2024-03-27T13:28:35.7348026Z created by github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).Start in goroutine 14116
2024-03-27T13:28:35.7348269Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/server.go:390 +0xf4
2024-03-27T13:28:35.7348275Z 
2024-03-27T13:28:35.7348379Z goroutine 14124 [select, 3 minutes]:
2024-03-27T13:28:35.7348729Z github.com/nspcc-dev/neo-go/pkg/core/mempool.(*Pool).notificationDispatcher(...)
2024-03-27T13:28:35.7348968Z 	D:/a/neo-go/neo-go/pkg/core/mempool/subscriptions.go:55
2024-03-27T13:28:35.7349419Z created by github.com/nspcc-dev/neo-go/pkg/core/mempool.(*Pool).RunSubscriptions in goroutine 14116
2024-03-27T13:28:35.7349688Z 	D:/a/neo-go/neo-go/pkg/core/mempool/subscriptions.go:13 +0xe5
2024-03-27T13:28:35.7349694Z 
2024-03-27T13:28:35.7349793Z goroutine 14129 [select, 3 minutes]:
2024-03-27T13:28:35.7350134Z github.com/nspcc-dev/neo-go/pkg/network.(*Server).broadcastTxLoop(0xc0001ebc08)
2024-03-27T13:28:35.7350351Z 	D:/a/neo-go/neo-go/pkg/network/server.go:1689 +0x33b
2024-03-27T13:28:35.7350745Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 14116
2024-03-27T13:28:35.7350993Z 	D:/a/neo-go/neo-go/pkg/network/server.go:293 +0x42b
2024-03-27T13:28:35.7350999Z 
2024-03-27T13:28:35.7351104Z goroutine 14121 [IO wait, 3 minutes]:
2024-03-27T13:28:35.7351249Z internal/poll.runtime_pollWait(0x485ecf80, 0x72)
2024-03-27T13:28:35.7351517Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/runtime/netpoll.go:345 +0x85
2024-03-27T13:28:35.7351680Z internal/poll.(*pollDesc).wait(0xc001b03340, 0x72, 0x0)
2024-03-27T13:28:35.7352018Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_poll_runtime.go:84 +0xb1
2024-03-27T13:28:35.7352155Z internal/poll.execIO(0xc001b031a0, 0xc0003e99f8)
2024-03-27T13:28:35.7352467Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:175 +0x271
2024-03-27T13:28:35.7352765Z internal/poll.(*FD).acceptOne(0xc001b03188, 0x49c, {0xc00084a0f0, 0x2, 0x2}, 0xc001b031a0)
2024-03-27T13:28:35.7353078Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:944 +0xf8
2024-03-27T13:28:35.7353238Z internal/poll.(*FD).Accept(0xc001b03188, 0xc00077dc70)
2024-03-27T13:28:35.7353585Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:978 +0x3cb
2024-03-27T13:28:35.7353723Z net.(*netFD).accept(0xc001b03188)
2024-03-27T13:28:35.7353981Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/fd_windows.go:178 +0x85
2024-03-27T13:28:35.7354094Z net.(*TCPListener).accept(0xc003bc4420)
2024-03-27T13:28:35.7354366Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/tcpsock_posix.go:159 +0x3e
2024-03-27T13:28:35.7354478Z net.(*TCPListener).Accept(0xc003bc4420)
2024-03-27T13:28:35.7354722Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/tcpsock.go:327 +0x65
2024-03-27T13:28:35.7354928Z net/http.(*Server).Serve(0xc000c5cb40, {0x141869d20, 0xc003bc4420})
2024-03-27T13:28:35.7355195Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/http/server.go:3255 +0x672
2024-03-27T13:28:35.7355321Z net/http/httptest.(*Server).goServe.func1()
2024-03-27T13:28:35.7355635Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/http/httptest/server.go:310 +0xbc
2024-03-27T13:28:35.7355859Z created by net/http/httptest.(*Server).goServe in goroutine 14116
2024-03-27T13:28:35.7356172Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/http/httptest/server.go:308 +0xa6
2024-03-27T13:28:35.7356177Z 
2024-03-27T13:28:35.7356295Z goroutine 14265 [chan receive, 3 minutes]:
2024-03-27T13:28:35.7356881Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.callWSGetRaw(0xc0001916c0, 0xc0021242c0, {0xc0001d2990, 0x8a}, 0xc000a8ab40)
2024-03-27T13:28:35.7357194Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:47 +0x176
2024-03-27T13:28:35.7357760Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.callSubscribe(0xc0001916c0, 0xc0021242c0, 0xc000a8ab40, {0xc0008e0190, 0x4f})
2024-03-27T13:28:35.7358071Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:78 +0x115
2024-03-27T13:28:35.7358595Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.TestFilteredNotaryRequestSubscriptions.func5(0xc0001916c0)
2024-03-27T13:28:35.7358908Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:404 +0xbf
2024-03-27T13:28:35.7359029Z testing.tRunner(0xc0001916c0, 0xc0036ba900)
2024-03-27T13:28:35.7359304Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:1689 +0x21f
2024-03-27T13:28:35.7359443Z created by testing.(*T).Run in goroutine 14116
2024-03-27T13:28:35.7359715Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:1742 +0x826
2024-03-27T13:28:35.7359725Z 
2024-03-27T13:28:35.7359819Z goroutine 5424 [runnable]:
2024-03-27T13:28:35.7360303Z github.com/nspcc-dev/neo-go/pkg/rpcclient.(*WSClient).notifySubscribers(0xc00053a8c0, {0xd4?, {0x0?, 0x0?}})
2024-03-27T13:28:35.7360543Z 	D:/a/neo-go/neo-go/pkg/rpcclient/wsclient.go:694 +0x172
2024-03-27T13:28:35.7366576Z github.com/nspcc-dev/neo-go/pkg/rpcclient.(*Internal).eventLoop(0xc00053a8c0)
2024-03-27T13:28:35.7366942Z 	D:/a/neo-go/neo-go/pkg/rpcclient/local.go:64 +0x47
2024-03-27T13:28:35.7367377Z created by github.com/nspcc-dev/neo-go/pkg/rpcclient.NewInternal in goroutine 5387
2024-03-27T13:28:35.7367609Z 	D:/a/neo-go/neo-go/pkg/rpcclient/local.go:45 +0x3cd
2024-03-27T13:28:35.7367871Z FAIL	github.com/nspcc-dev/neo-go/pkg/services/rpcsrv	900.168s
@AnnaShaleva AnnaShaleva added bug Something isn't working test Unit tests U2 Seriously planned S4 Routine I4 No visible changes labels Mar 27, 2024
@AnnaShaleva AnnaShaleva added this to the v0.106.0 milestone Mar 27, 2024
@AnnaShaleva AnnaShaleva mentioned this issue Mar 27, 2024
Merged
@AliceInHunterland
Copy link
Contributor

tried the same approach as the one used in #3368 here and had the same Run tests (windows-2022, 1.22) https://github.com/nspcc-dev/neo-go/compare/dc9b9c0cdf1585bcc734e7ab210c607e27d5235b..e10c584d422d3997b68128231f05a0c68e67aa49

AliceInHunterland added a commit that referenced this issue Mar 29, 2024
@AliceInHunterland
rpcsrv: fix TestFilteredNotaryRequestSubscriptions
e3adaac 
Add closing of the server,as it does in others subscription tests.

Close #3378

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
@AliceInHunterland AliceInHunterland mentioned this issue Mar 29, 2024
Closed
AliceInHunterland added a commit that referenced this issue Mar 29, 2024
@AliceInHunterland
rpcsrv: fix TestFilteredNotaryRequestSubscriptions
2f8020c 
Add closing of the server, as it does in other subscription tests.

Close #3378

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
AnnaShaleva added a commit that referenced this issue Apr 1, 2024
@AnnaShaleva
rpcsrv: properly cleanup WS reader in tests
d9f66e7 
Close #3378.

Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
@AnnaShaleva AnnaShaleva mentioned this issue Apr 1, 2024
Merged
AnnaShaleva added a commit that referenced this issue Apr 1, 2024
@AnnaShaleva
rpcsrv: properly cleanup WS reader in tests
1b072ea 
Close #3378.

Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
AnnaShaleva added a commit that referenced this issue Apr 1, 2024
@AnnaShaleva
rpcsrv: properly cleanup WS reader in tests
57d82c1 
Close #3378.

Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
@AliceInHunterland
Copy link
Contributor

Not fixed, still have it on Windows, failure discovered in #3387

NAME  TestFilteredNotaryRequestSubscriptions
2024-04-01T16:27:45.0636903Z     subscription_test.go:36: 
2024-04-01T16:27:45.0637406Z         	Error Trace:	D:/a/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:36
2024-04-01T16:27:45.0638020Z         	            				C:/hostedtoolcache/windows/go/1.22.1/x64/src/runtime/asm_amd64.s:1695
2024-04-01T16:27:45.0638228Z         	Error:      	Received unexpected error:
2024-04-01T16:27:45.0638709Z         	            	read tcp 127.0.0.1:58641->127.0.0.1:58640: i/o timeout
2024-04-01T16:27:45.0639025Z         	Test:       	TestFilteredNotaryRequestSubscriptions
2024-04-01T16:27:45.0639728Z     logger.go:146: 2024-04-01T16:24:24.578Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[notary_request_event ]"}
2024-04-01T16:27:45.0640436Z     logger.go:146: 2024-04-01T16:24:25.157Z	INFO	persisted to disk	{"blocks": 10, "keys": 825, "headerHeight": 23, "blockHeight": 23, "took": "0s"}
2024-04-01T16:27:45.0640551Z panic: test timed out after 15m0s
2024-04-01T16:27:45.0640633Z running tests:
2024-04-01T16:27:45.0640816Z 	TestFilteredNotaryRequestSubscriptions (1m45s)
2024-04-01T16:27:45.0641059Z 	TestFilteredNotaryRequestSubscriptions/matching_sender (1m44s)
2024-04-01T16:27:45.0641068Z 
2024-04-01T16:27:45.0641168Z goroutine 13877 [running]:
2024-04-01T16:27:45.0641270Z testing.(*M).startAlarm.func1()
2024-04-01T16:27:45.0641552Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:2366 +0x265
2024-04-01T16:27:45.0641651Z created by time.goFunc
2024-04-01T16:27:45.0641895Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/time/sleep.go:177 +0x45
2024-04-01T16:27:45.0641902Z

@AnnaShaleva AnnaShaleva mentioned this issue Apr 2, 2024
Merged
@AnnaShaleva
Copy link
Member Author

AnnaShaleva commented Apr 3, 2024 •
edited
Loading

Still not fixed on fresh master, failure discovered in #3396 test run:

2024-04-03T16:03:54.3008170Z === RUN   TestFilteredNotaryRequestSubscriptions
2024-04-03T16:03:54.3008790Z     logger.go:146: 2024-04-03T16:02:34.124Z	INFO	initial gas supply is not set or wrong, setting default value	{"InitialGASSupply": "52000000"}
2024-04-03T16:03:54.3009330Z     logger.go:146: 2024-04-03T16:02:34.124Z	INFO	MaxBlockSize is not set or wrong, setting default value	{"MaxBlockSize": 262144}
2024-04-03T16:03:54.3009910Z     logger.go:146: 2024-04-03T16:02:34.124Z	INFO	MaxBlockSystemFee is not set or wrong, setting default value	{"MaxBlockSystemFee": 900000000000}
2024-04-03T16:03:54.3010500Z     logger.go:146: 2024-04-03T16:02:34.124Z	INFO	MaxTransactionsPerBlock is not set or wrong, using default value	{"MaxTransactionsPerBlock": 512}
2024-04-03T16:03:54.3011110Z     logger.go:146: 2024-04-03T16:02:34.124Z	INFO	MaxValidUntilBlockIncrement is not set or wrong, using default value	{"MaxValidUntilBlockIncrement": 5760}
2024-04-03T16:03:54.3011480Z     logger.go:146: 2024-04-03T16:02:34.125Z	INFO	no storage version found! creating genesis block
2024-04-03T16:03:54.3012010Z     logger.go:146: 2024-04-03T16:02:34.128Z	INFO	ExtensiblePoolSize is not set or wrong, using default value	{"ExtensiblePoolSize": 20}
2024-04-03T16:03:54.3012520Z     logger.go:146: 2024-04-03T16:02:34.129Z	INFO	SessionPoolSize is not set or wrong, setting default value	{"SessionPoolSize": 20}
2024-04-03T16:03:54.3013100Z     logger.go:146: 2024-04-03T16:02:34.129Z	INFO	MaxIteratorResultItems is not set or wrong, setting default value	{"MaxIteratorResultItems": 100}
2024-04-03T16:03:54.3013630Z     logger.go:146: 2024-04-03T16:02:34.129Z	INFO	MaxFindResultItems is not set or wrong, setting default value	{"MaxFindResultItems": 100}
2024-04-03T16:03:54.3014140Z     logger.go:146: 2024-04-03T16:02:34.129Z	INFO	MaxNEP11Tokens is not set or wrong, setting default value	{"MaxNEP11Tokens": 100}
2024-04-03T16:03:54.3014720Z     logger.go:146: 2024-04-03T16:02:34.129Z	INFO	MaxRequestBodyBytes is not set or wong, setting default value	{"MaxRequestBodyBytes": 5242880}
2024-04-03T16:03:54.3019650Z     logger.go:146: 2024-04-03T16:02:34.129Z	INFO	MaxRequestHeaderBytes is not set or wong, setting default value	{"MaxRequestHeaderBytes": 1048576}
2024-04-03T16:03:54.3020220Z     logger.go:146: 2024-04-03T16:02:34.129Z	INFO	MaxWebSocketClients is not set or wrong, setting default value	{"MaxWebSocketClients": 64}
2024-04-03T16:03:54.3020590Z     logger.go:146: 2024-04-03T16:02:34.129Z	INFO	starting rpc-server	{"endpoint": "127.0.0.1:0"}
2024-04-03T16:03:54.3020960Z     logger.go:146: 2024-04-03T16:02:34.438Z	INFO	node started	{"blockHeight": 0, "headerHeight": 0}
2024-04-03T16:03:54.3021330Z     logger.go:146: 2024-04-03T16:02:34.438Z	INFO	node reached synchronized state, starting services
2024-04-03T16:03:54.3021840Z     logger.go:146: 2024-04-03T16:02:34.441Z	DEBUG	done processing headers	{"headerIndex": 1, "blockHeight": 0, "took": "760.875µs"}
2024-04-03T16:03:54.3022350Z     logger.go:146: 2024-04-03T16:02:34.612Z	DEBUG	done processing headers	{"headerIndex": 2, "blockHeight": 1, "took": "465.792µs"}
2024-04-03T16:03:54.3022840Z     logger.go:146: 2024-04-03T16:02:34.614Z	DEBUG	done processing headers	{"headerIndex": 3, "blockHeight": 2, "took": "441.5µs"}
2024-04-03T16:03:54.3023350Z     logger.go:146: 2024-04-03T16:02:34.615Z	DEBUG	done processing headers	{"headerIndex": 4, "blockHeight": 3, "took": "431.208µs"}
2024-04-03T16:03:54.3023910Z     logger.go:146: 2024-04-03T16:02:34.617Z	DEBUG	done processing headers	{"headerIndex": 5, "blockHeight": 4, "took": "665.125µs"}
2024-04-03T16:03:54.3024940Z     logger.go:146: 2024-04-03T16:02:34.617Z	INFO	bad notification	{"contract": "565cff9508ebc75aadd7fe59f38dac610ab6093c", "event": "Transfer", "error": "notification Transfer is invalid: parameter 0 type mismatch: Hash160 (manifest) vs ByteString (notification)"}
2024-04-03T16:03:54.3025450Z     logger.go:146: 2024-04-03T16:02:34.756Z	DEBUG	done processing headers	{"headerIndex": 6, "blockHeight": 5, "took": "137.680875ms"}
2024-04-03T16:03:54.3025950Z     logger.go:146: 2024-04-03T16:02:34.758Z	DEBUG	done processing headers	{"headerIndex": 7, "blockHeight": 6, "took": "451.5µs"}
2024-04-03T16:03:54.3026520Z     logger.go:146: 2024-04-03T16:02:34.759Z	DEBUG	done processing headers	{"headerIndex": 8, "blockHeight": 7, "took": "439.208µs"}
2024-04-03T16:03:54.3027050Z     logger.go:146: 2024-04-03T16:02:34.760Z	DEBUG	done processing headers	{"headerIndex": 9, "blockHeight": 8, "took": "428.791µs"}
2024-04-03T16:03:54.3027590Z     logger.go:146: 2024-04-03T16:02:34.924Z	DEBUG	done processing headers	{"headerIndex": 10, "blockHeight": 9, "took": "161.68375ms"}
2024-04-03T16:03:54.3028100Z     logger.go:146: 2024-04-03T16:02:35.172Z	DEBUG	done processing headers	{"headerIndex": 11, "blockHeight": 10, "took": "612.125µs"}
2024-04-03T16:03:54.3028600Z     logger.go:146: 2024-04-03T16:02:35.175Z	DEBUG	done processing headers	{"headerIndex": 12, "blockHeight": 11, "took": "440.125µs"}
2024-04-03T16:03:54.3029100Z     logger.go:146: 2024-04-03T16:02:35.177Z	DEBUG	done processing headers	{"headerIndex": 13, "blockHeight": 12, "took": "430.125µs"}
2024-04-03T16:03:54.3029670Z     logger.go:146: 2024-04-03T16:02:35.242Z	INFO	persisted to disk	{"blocks": 12, "keys": 460, "headerHeight": 13, "blockHeight": 12, "took": "403.417µs"}
2024-04-03T16:03:54.3030180Z     logger.go:146: 2024-04-03T16:02:35.242Z	DEBUG	done processing headers	{"headerIndex": 14, "blockHeight": 13, "took": "598.625µs"}
2024-04-03T16:03:54.3030680Z     logger.go:146: 2024-04-03T16:02:35.244Z	DEBUG	done processing headers	{"headerIndex": 15, "blockHeight": 14, "took": "437.291µs"}
2024-04-03T16:03:54.3031170Z     logger.go:146: 2024-04-03T16:02:35.246Z	DEBUG	done processing headers	{"headerIndex": 16, "blockHeight": 15, "took": "489.417µs"}
2024-04-03T16:03:54.3031670Z     logger.go:146: 2024-04-03T16:02:35.248Z	DEBUG	done processing headers	{"headerIndex": 17, "blockHeight": 16, "took": "444.5µs"}
2024-04-03T16:03:54.3032220Z     logger.go:146: 2024-04-03T16:02:35.371Z	DEBUG	done processing headers	{"headerIndex": 18, "blockHeight": 17, "took": "120.251333ms"}
2024-04-03T16:03:54.3032730Z     logger.go:146: 2024-04-03T16:02:35.373Z	DEBUG	done processing headers	{"headerIndex": 19, "blockHeight": 18, "took": "473.708µs"}
2024-04-03T16:03:54.3033230Z     logger.go:146: 2024-04-03T16:02:35.374Z	DEBUG	done processing headers	{"headerIndex": 20, "blockHeight": 19, "took": "421.583µs"}
2024-04-03T16:03:54.3033730Z     logger.go:146: 2024-04-03T16:02:35.376Z	DEBUG	done processing headers	{"headerIndex": 21, "blockHeight": 20, "took": "419.625µs"}
2024-04-03T16:03:54.3034240Z     logger.go:146: 2024-04-03T16:02:35.377Z	DEBUG	done processing headers	{"headerIndex": 22, "blockHeight": 21, "took": "434.25µs"}
2024-04-03T16:03:54.3034730Z     logger.go:146: 2024-04-03T16:02:35.386Z	DEBUG	done processing headers	{"headerIndex": 23, "blockHeight": 22, "took": "471.708µs"}
2024-04-03T16:03:54.3035550Z     logger.go:146: 2024-04-03T16:02:35.387Z	WARN	contract invocation failed	{"tx": "82279bfe9bada282ca0f8cb8e0bb124b921af36f00c69a518320322c6f4fef60", "block": 23, "error": "at instruction 0 (ABORT): ABORT"}
2024-04-03T16:03:54.3035730Z === RUN   TestFilteredNotaryRequestSubscriptions/matching_sender
2024-04-03T16:03:54.3035860Z === NAME  TestFilteredNotaryRequestSubscriptions
2024-04-03T16:03:54.3036370Z     logger.go:146: 2024-04-03T16:02:35.479Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[notary_request_event ]"}
2024-04-03T16:03:54.3036810Z     logger.go:146: 2024-04-03T16:02:35.843Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[0]"}
2024-04-03T16:03:54.3036990Z === RUN   TestFilteredNotaryRequestSubscriptions/matching_signer
2024-04-03T16:03:54.3037110Z === NAME  TestFilteredNotaryRequestSubscriptions
2024-04-03T16:03:54.3037610Z     logger.go:146: 2024-04-03T16:02:36.197Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[notary_request_event ]"}
2024-04-03T16:03:54.3038190Z     logger.go:146: 2024-04-03T16:02:36.342Z	INFO	persisted to disk	{"blocks": 11, "keys": 848, "headerHeight": 23, "blockHeight": 23, "took": "342.458µs"}
2024-04-03T16:03:54.3038620Z     logger.go:146: 2024-04-03T16:02:36.881Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[0]"}
2024-04-03T16:03:54.3038860Z === RUN   TestFilteredNotaryRequestSubscriptions/matching_type
2024-04-03T16:03:54.3039000Z === NAME  TestFilteredNotaryRequestSubscriptions
2024-04-03T16:03:54.3039530Z     logger.go:146: 2024-04-03T16:02:37.343Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[notary_request_event ]"}
2024-04-03T16:03:54.3039960Z     logger.go:146: 2024-04-03T16:02:37.812Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[0]"}
2024-04-03T16:03:54.3040190Z === RUN   TestFilteredNotaryRequestSubscriptions/matching_sender,_signer_and_type
2024-04-03T16:03:54.3040310Z === NAME  TestFilteredNotaryRequestSubscriptions
2024-04-03T16:03:54.3040810Z     logger.go:146: 2024-04-03T16:02:38.192Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[notary_request_event ]"}
2024-04-03T16:03:54.3041240Z     logger.go:146: 2024-04-03T16:02:38.896Z	DEBUG	processing rpc request	{"method": "unsubscribe", "params": "[0]"}
2024-04-03T16:03:54.3041330Z panic: test timed out after 15m0s
2024-04-03T16:03:54.3041390Z running tests:
2024-04-03T16:03:54.3041530Z 	TestFilteredNotaryRequestSubscriptions (6s)
2024-04-03T16:03:54.3041530Z 
2024-04-03T16:03:54.3041610Z goroutine 15514 [running]:
2024-04-03T16:03:54.3041690Z testing.(*M).startAlarm.func1()
2024-04-03T16:03:54.3041940Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/testing/testing.go:2366 +0x1dc
2024-04-03T16:03:54.3042010Z created by time.goFunc
2024-04-03T16:03:54.3042240Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/time/sleep.go:177 +0x44
2024-04-03T16:03:54.3042250Z 
2024-04-03T16:03:54.3042350Z goroutine 1 [chan receive]:
2024-04-03T16:03:54.3042510Z testing.(*T).Run(0xc0001c21a0, {0x105496c0e, 0x26}, 0x105a019d8)
2024-04-03T16:03:54.3042760Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/testing/testing.go:1750 +0x604
2024-04-03T16:03:54.3042840Z testing.runTests.func1(0xc0001c21a0)
2024-04-03T16:03:54.3043090Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/testing/testing.go:2161 +0x84
2024-04-03T16:03:54.3043180Z testing.tRunner(0xc0001c21a0, 0xc0002adb08)
2024-04-03T16:03:54.3043420Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/testing/testing.go:1689 +0x184
2024-04-03T16:03:54.3043670Z testing.runTests(0xc000186c18, {0x1062d1e20, 0x31, 0x31}, {0x1045608a4?, 0x0?, 0x1062dec20?})
2024-04-03T16:03:54.3043910Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/testing/testing.go:2159 +0x6e4
2024-04-03T16:03:54.3043990Z testing.(*M).Run(0xc0001a2140)
2024-04-03T16:03:54.3044230Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/testing/testing.go:2027 +0xb70
2024-04-03T16:03:54.3044290Z main.main()
2024-04-03T16:03:54.3044370Z 	_testmain.go:145 +0x298
2024-04-03T16:03:54.3044370Z 
2024-04-03T16:03:54.3044450Z goroutine 15368 [chan receive]:
2024-04-03T16:03:54.3044750Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.initCleanServerAndWSClient.func1()
2024-04-03T16:03:54.3045060Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:102 +0x7c
2024-04-03T16:03:54.3045140Z testing.(*common).Cleanup.func1()
2024-04-03T16:03:54.3045380Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/testing/testing.go:1175 +0x148
2024-04-03T16:03:54.3045490Z testing.(*common).runCleanup(0xc000014000, 0x0)
2024-04-03T16:03:54.3045730Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/testing/testing.go:1353 +0x1ac
2024-04-03T16:03:54.3045800Z testing.tRunner.func2()
2024-04-03T16:03:54.3046040Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/testing/testing.go:1683 +0x4c
2024-04-03T16:03:54.3046130Z testing.tRunner(0xc000014000, 0x105a019d8)
2024-04-03T16:03:54.3046370Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/testing/testing.go:1695 +0x1ac
2024-04-03T16:03:54.3046460Z created by testing.(*T).Run in goroutine 1
2024-04-03T16:03:54.3046700Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/testing/testing.go:1742 +0x5e8
2024-04-03T16:03:54.3046700Z 
2024-04-03T16:03:54.3046770Z goroutine 15120 [select]:
2024-04-03T16:03:54.3047040Z github.com/nspcc-dev/neo-go/pkg/network.(*Server).broadcastTxLoop(0xc001e5d008)
2024-04-03T16:03:54.3047350Z 	/Users/runner/work/neo-go/neo-go/pkg/network/server.go:1689 +0x200
2024-04-03T16:03:54.3047680Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 15368
2024-04-03T16:03:54.3047900Z 	/Users/runner/work/neo-go/neo-go/pkg/network/server.go:293 +0x328
2024-04-03T16:03:54.3047910Z 
2024-04-03T16:03:54.3047980Z goroutine 15395 [chan receive]:
2024-04-03T16:03:54.3048230Z github.com/nspcc-dev/neo-go/pkg/network/bqueue.(*Queue).Run(0xc0020aec80)
2024-04-03T16:03:54.3048470Z 	/Users/runner/work/neo-go/neo-go/pkg/network/bqueue/queue.go:60 +0x80
2024-04-03T16:03:54.3048750Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 15368
2024-04-03T16:03:54.3048970Z 	/Users/runner/work/neo-go/neo-go/pkg/network/server.go:296 +0x484
2024-04-03T16:03:54.3048980Z 
2024-04-03T16:03:54.3049050Z goroutine 15121 [select]:
2024-04-03T16:03:54.3049320Z github.com/nspcc-dev/neo-go/pkg/network.(*Server).relayBlocksLoop(0xc001e5d008)
2024-04-03T16:03:54.3049540Z 	/Users/runner/work/neo-go/neo-go/pkg/network/server.go:1589 +0x158
2024-04-03T16:03:54.3049830Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 15368
2024-04-03T16:03:54.3050050Z 	/Users/runner/work/neo-go/neo-go/pkg/network/server.go:294 +0x38c
2024-04-03T16:03:54.3050050Z 
2024-04-03T16:03:54.3050130Z goroutine 4752 [runnable]:
2024-04-03T16:03:54.3050490Z github.com/nspcc-dev/neo-go/pkg/rpcclient.(*WSClient).notifySubscribers(0xc000741880, {0x0?, {0x0?, 0x0?}})
2024-04-03T16:03:54.3050740Z 	/Users/runner/work/neo-go/neo-go/pkg/rpcclient/wsclient.go:683 +0x468
2024-04-03T16:03:54.3051020Z github.com/nspcc-dev/neo-go/pkg/rpcclient.(*Internal).eventLoop(0xc000741880)
2024-04-03T16:03:54.3051240Z 	/Users/runner/work/neo-go/neo-go/pkg/rpcclient/local.go:64 +0x3c
2024-04-03T16:03:54.3051520Z created by github.com/nspcc-dev/neo-go/pkg/rpcclient.NewInternal in goroutine 4761
2024-04-03T16:03:54.3051740Z 	/Users/runner/work/neo-go/neo-go/pkg/rpcclient/local.go:45 +0x2fc
2024-04-03T16:03:54.3051740Z 
2024-04-03T16:03:54.3051820Z goroutine 15401 [select]:
2024-04-03T16:03:54.3052060Z github.com/nspcc-dev/neo-go/pkg/network.(*Server).runProto(0xc001e5d008)
2024-04-03T16:03:54.3052280Z 	/Users/runner/work/neo-go/neo-go/pkg/network/server.go:553 +0x17c
2024-04-03T16:03:54.3052550Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).run in goroutine 15397
2024-04-03T16:03:54.3052770Z 	/Users/runner/work/neo-go/neo-go/pkg/network/server.go:453 +0x1c8
2024-04-03T16:03:54.3052770Z 
2024-04-03T16:03:54.3052840Z goroutine 15375 [select]:
2024-04-03T16:03:54.3053140Z github.com/nspcc-dev/neo-go/pkg/core.(*Blockchain).notificationDispatcher(0xc0007bc908)
2024-04-03T16:03:54.3053370Z 	/Users/runner/work/neo-go/neo-go/pkg/core/blockchain.go:1336 +0x304
2024-04-03T16:03:54.3053650Z created by github.com/nspcc-dev/neo-go/pkg/core.(*Blockchain).Run in goroutine 15370
2024-04-03T16:03:54.3053880Z 	/Users/runner/work/neo-go/neo-go/pkg/core/blockchain.go:1071 +0x120
2024-04-03T16:03:54.3053890Z 
2024-04-03T16:03:54.3053960Z goroutine 15371 [select]:
2024-04-03T16:03:54.3054260Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).handleSubEvents(0xc0002a1688)
2024-04-03T16:03:54.3054520Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/server.go:2921 +0x5dc
2024-04-03T16:03:54.3054840Z created by github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).Start in goroutine 15368
2024-04-03T16:03:54.3055090Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/server.go:390 +0xc0
2024-04-03T16:03:54.3055090Z 
2024-04-03T16:03:54.3055170Z goroutine 15119 [select]:
2024-04-03T16:03:54.3055420Z github.com/nspcc-dev/neo-go/pkg/network.(*Server).txHandlerLoop(0xc001e5d008)
2024-04-03T16:03:54.3055650Z 	/Users/runner/work/neo-go/neo-go/pkg/network/server.go:1155 +0x178
2024-04-03T16:03:54.3055930Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 15368
2024-04-03T16:03:54.3056150Z 	/Users/runner/work/neo-go/neo-go/pkg/network/server.go:291 +0x250
2024-04-03T16:03:54.3056200Z 
2024-04-03T16:03:54.3056280Z goroutine 5100 [runnable]:
2024-04-03T16:03:54.3056390Z context.(*cancelCtx).Done(0xc0005aacd0)
2024-04-03T16:03:54.3056650Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/context/context.go:438 +0x18c
2024-04-03T16:03:54.3056910Z github.com/nspcc-dev/neo-go/pkg/rpcclient.(*Internal).eventLoop(0xc000741a40)
2024-04-03T16:03:54.3057130Z 	/Users/runner/work/neo-go/neo-go/pkg/rpcclient/local.go:55 +0x60
2024-04-03T16:03:54.3057410Z created by github.com/nspcc-dev/neo-go/pkg/rpcclient.NewInternal in goroutine 5094
2024-04-03T16:03:54.3057630Z 	/Users/runner/work/neo-go/neo-go/pkg/rpcclient/local.go:45 +0x2fc
2024-04-03T16:03:54.3057630Z 
2024-04-03T16:03:54.3057710Z goroutine 5072 [runnable]:
2024-04-03T16:03:54.3058080Z github.com/nspcc-dev/neo-go/pkg/rpcclient.(*WSClient).notifySubscribers(0xc0005b36c0, {0xbc?, {0x0?, 0x0?}})
2024-04-03T16:03:54.3058320Z 	/Users/runner/work/neo-go/neo-go/pkg/rpcclient/wsclient.go:694 +0x104
2024-04-03T16:03:54.3058570Z github.com/nspcc-dev/neo-go/pkg/rpcclient.(*Internal).eventLoop(0xc0005b36c0)
2024-04-03T16:03:54.3058790Z 	/Users/runner/work/neo-go/neo-go/pkg/rpcclient/local.go:64 +0x3c
2024-04-03T16:03:54.3059070Z created by github.com/nspcc-dev/neo-go/pkg/rpcclient.NewInternal in goroutine 5066
2024-04-03T16:03:54.3059290Z 	/Users/runner/work/neo-go/neo-go/pkg/rpcclient/local.go:45 +0x2fc
2024-04-03T16:03:54.3059290Z 
2024-04-03T16:03:54.3059360Z goroutine 15370 [select]:
2024-04-03T16:03:54.3059580Z github.com/nspcc-dev/neo-go/pkg/core.(*Blockchain).Run(0xc0007bc908)
2024-04-03T16:03:54.3059840Z 	/Users/runner/work/neo-go/neo-go/pkg/core/blockchain.go:1074 +0x220
2024-04-03T16:03:54.3060260Z created by github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.getUnitTestChainWithCustomConfig in goroutine 15368
2024-04-03T16:03:54.3060560Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/server_helper_test.go:85 +0x554
2024-04-03T16:03:54.3060570Z 
2024-04-03T16:03:54.3060640Z goroutine 15394 [chan receive]:
2024-04-03T16:03:54.3060890Z github.com/nspcc-dev/neo-go/pkg/network/bqueue.(*Queue).Run(0xc0020aec00)
2024-04-03T16:03:54.3061130Z 	/Users/runner/work/neo-go/neo-go/pkg/network/bqueue/queue.go:60 +0x80
2024-04-03T16:03:54.3061410Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 15368
2024-04-03T16:03:54.3061630Z 	/Users/runner/work/neo-go/neo-go/pkg/network/server.go:295 +0x408
2024-04-03T16:03:54.3061630Z 
2024-04-03T16:03:54.3061710Z goroutine 15396 [IO wait]:
2024-04-03T16:03:54.3061830Z internal/poll.runtime_pollWait(0x14fbd8030, 0x72)
2024-04-03T16:03:54.3062070Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/runtime/netpoll.go:345 +0xa0
2024-04-03T16:03:54.3062200Z internal/poll.(*pollDesc).wait(0xc0006fff20, 0x72, 0x0)
2024-04-03T16:03:54.3062500Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/internal/poll/fd_poll_runtime.go:84 +0xb8
2024-04-03T16:03:54.3062590Z internal/poll.(*pollDesc).waitRead(...)
2024-04-03T16:03:54.3062860Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/internal/poll/fd_poll_runtime.go:89
2024-04-03T16:03:54.3062950Z internal/poll.(*FD).Accept(0xc0006fff00)
2024-04-03T16:03:54.3063210Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/internal/poll/fd_unix.go:611 +0x3a8
2024-04-03T16:03:54.3063290Z net.(*netFD).accept(0xc0006fff00)
2024-04-03T16:03:54.3063510Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/fd_unix.go:172 +0x38
2024-04-03T16:03:54.3063600Z net.(*TCPListener).accept(0xc0027e03c0)
2024-04-03T16:03:54.3063910Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/tcpsock_posix.go:159 +0x3c
2024-04-03T16:03:54.3064000Z net.(*TCPListener).Accept(0xc0027e03c0)
2024-04-03T16:03:54.3064220Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/tcpsock.go:327 +0x68
2024-04-03T16:03:54.3064480Z github.com/nspcc-dev/neo-go/pkg/network.(*TCPTransport).Accept(0xc002208540)
2024-04-03T16:03:54.3064740Z 	/Users/runner/work/neo-go/neo-go/pkg/network/tcp_transport.go:78 +0x334
2024-04-03T16:03:54.3065080Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 15368
2024-04-03T16:03:54.3065670Z 	/Users/runner/work/neo-go/neo-go/pkg/network/server.go:298 +0x4a8
2024-04-03T16:03:54.3065720Z 
2024-04-03T16:03:54.3065830Z goroutine 15372 [IO wait]:
2024-04-03T16:03:54.3065980Z internal/poll.runtime_pollWait(0x14fa86928, 0x72)
2024-04-03T16:03:54.3066270Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/runtime/netpoll.go:345 +0xa0
2024-04-03T16:03:54.3066420Z internal/poll.(*pollDesc).wait(0xc0020aeda0, 0x72, 0x0)
2024-04-03T16:03:54.3066740Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/internal/poll/fd_poll_runtime.go:84 +0xb8
2024-04-03T16:03:54.3066840Z internal/poll.(*pollDesc).waitRead(...)
2024-04-03T16:03:54.3067120Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/internal/poll/fd_poll_runtime.go:89
2024-04-03T16:03:54.3067210Z internal/poll.(*FD).Accept(0xc0020aed80)
2024-04-03T16:03:54.3067480Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/internal/poll/fd_unix.go:611 +0x3a8
2024-04-03T16:03:54.3067560Z net.(*netFD).accept(0xc0020aed80)
2024-04-03T16:03:54.3067800Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/fd_unix.go:172 +0x38
2024-04-03T16:03:54.3067890Z net.(*TCPListener).accept(0xc002111520)
2024-04-03T16:03:54.3068140Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/tcpsock_posix.go:159 +0x3c
2024-04-03T16:03:54.3068230Z net.(*TCPListener).Accept(0xc002111520)
2024-04-03T16:03:54.3068450Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/tcpsock.go:327 +0x68
2024-04-03T16:03:54.3068620Z net/http.(*Server).Serve(0xc001171d10, {0x105a17388, 0xc002111520})
2024-04-03T16:03:54.3068910Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/http/server.go:3255 +0x488
2024-04-03T16:03:54.3069250Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).Start.func1(0xc001171d10)
2024-04-03T16:03:54.3069510Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/server.go:403 +0x5c
2024-04-03T16:03:54.3069850Z created by github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).Start in goroutine 15368
2024-04-03T16:03:54.3070120Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/server.go:402 +0x168
2024-04-03T16:03:54.3070130Z 
2024-04-03T16:03:54.3070200Z goroutine 15116 [select]:
2024-04-03T16:03:54.3070490Z github.com/nspcc-dev/neo-go/pkg/core/mempool.(*Pool).notificationDispatcher(...)
2024-04-03T16:03:54.3070730Z 	/Users/runner/work/neo-go/neo-go/pkg/core/mempool/subscriptions.go:55
2024-04-03T16:03:54.3071100Z created by github.com/nspcc-dev/neo-go/pkg/core/mempool.(*Pool).RunSubscriptions in goroutine 15368
2024-04-03T16:03:54.3071370Z 	/Users/runner/work/neo-go/neo-go/pkg/core/mempool/subscriptions.go:13 +0xc0
2024-04-03T16:03:54.3071380Z 
2024-04-03T16:03:54.3071450Z goroutine 15117 [select]:
2024-04-03T16:03:54.3071720Z github.com/nspcc-dev/neo-go/pkg/network.(*Server).txHandlerLoop(0xc001e5d008)
2024-04-03T16:03:54.3071950Z 	/Users/runner/work/neo-go/neo-go/pkg/network/server.go:1155 +0x178
2024-04-03T16:03:54.3072250Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 15368
2024-04-03T16:03:54.3072480Z 	/Users/runner/work/neo-go/neo-go/pkg/network/server.go:291 +0x250
2024-04-03T16:03:54.3072480Z 
2024-04-03T16:03:54.3072560Z goroutine 15373 [IO wait]:
2024-04-03T16:03:54.3072690Z internal/poll.runtime_pollWait(0x14fa86070, 0x72)
2024-04-03T16:03:54.3072930Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/runtime/netpoll.go:345 +0xa0
2024-04-03T16:03:54.3073070Z internal/poll.(*pollDesc).wait(0xc0020aee20, 0x72, 0x0)
2024-04-03T16:03:54.3073380Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/internal/poll/fd_poll_runtime.go:84 +0xb8
2024-04-03T16:03:54.3073470Z internal/poll.(*pollDesc).waitRead(...)
2024-04-03T16:03:54.3073760Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/internal/poll/fd_poll_runtime.go:89
2024-04-03T16:03:54.3073860Z internal/poll.(*FD).Accept(0xc0020aee00)
2024-04-03T16:03:54.3074140Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/internal/poll/fd_unix.go:611 +0x3a8
2024-04-03T16:03:54.3074230Z net.(*netFD).accept(0xc0020aee00)
2024-04-03T16:03:54.3074580Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/fd_unix.go:172 +0x38
2024-04-03T16:03:54.3074700Z net.(*TCPListener).accept(0xc002111540)
2024-04-03T16:03:54.3074960Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/tcpsock_posix.go:159 +0x3c
2024-04-03T16:03:54.3075050Z net.(*TCPListener).Accept(0xc002111540)
2024-04-03T16:03:54.3075280Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/tcpsock.go:327 +0x68
2024-04-03T16:03:54.3075450Z net/http.(*Server).Serve(0xc001171e00, {0x105a17388, 0xc002111540})
2024-04-03T16:03:54.3075700Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/http/server.go:3255 +0x488
2024-04-03T16:03:54.3075810Z net/http/httptest.(*Server).goServe.func1()
2024-04-03T16:03:54.3076090Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/http/httptest/server.go:310 +0xb4
2024-04-03T16:03:54.3076270Z created by net/http/httptest.(*Server).goServe in goroutine 15368
2024-04-03T16:03:54.3076550Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/http/httptest/server.go:308 +0x9c
2024-04-03T16:03:54.3076560Z 
2024-04-03T16:03:54.3076640Z goroutine 15115 [IO wait]:
2024-04-03T16:03:54.3076760Z internal/poll.runtime_pollWait(0x14fa6aac0, 0x72)
2024-04-03T16:03:54.3077010Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/runtime/netpoll.go:345 +0xa0
2024-04-03T16:03:54.3077150Z internal/poll.(*pollDesc).wait(0xc0020aef20, 0x72, 0x0)
2024-04-03T16:03:54.3077460Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/internal/poll/fd_poll_runtime.go:84 +0xb8
2024-04-03T16:03:54.3077550Z internal/poll.(*pollDesc).waitRead(...)
2024-04-03T16:03:54.3077870Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/internal/poll/fd_poll_runtime.go:89
2024-04-03T16:03:54.3078050Z internal/poll.(*FD).Read(0xc0020aef00, {0xc002004000, 0x1000, 0x1000})
2024-04-03T16:03:54.3078330Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/internal/poll/fd_unix.go:164 +0x320
2024-04-03T16:03:54.3078490Z net.(*netFD).Read(0xc0020aef00, {0xc002004000, 0x1000, 0x1000})
2024-04-03T16:03:54.3078720Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/fd_posix.go:55 +0x48
2024-04-03T16:03:54.3078880Z net.(*conn).Read(0xc000072568, {0xc002004000, 0x1000, 0x1000})
2024-04-03T16:03:54.3079090Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/net.go:179 +0x88
2024-04-03T16:03:54.3079180Z bufio.(*Reader).fill(0xc000b22f60)
2024-04-03T16:03:54.3079410Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/bufio/bufio.go:110 +0x21c
2024-04-03T16:03:54.3079500Z bufio.(*Reader).Peek(0xc000b22f60, 0x2)
2024-04-03T16:03:54.3079730Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/bufio/bufio.go:148 +0xb4
2024-04-03T16:03:54.3079890Z github.com/gorilla/websocket.(*Conn).read(0xc000801a20, 0x2)
2024-04-03T16:03:54.3080150Z 	/Users/runner/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/conn.go:378 +0x4c
2024-04-03T16:03:54.3080330Z github.com/gorilla/websocket.(*Conn).advanceFrame(0xc000801a20)
2024-04-03T16:03:54.3080590Z 	/Users/runner/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/conn.go:824 +0xc4
2024-04-03T16:03:54.3080760Z github.com/gorilla/websocket.(*Conn).NextReader(0xc000801a20)
2024-04-03T16:03:54.3081020Z 	/Users/runner/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/conn.go:1034 +0x1b8
2024-04-03T16:03:54.3081200Z github.com/gorilla/websocket.(*Conn).ReadMessage(0xc000801a20)
2024-04-03T16:03:54.3081450Z 	/Users/runner/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/conn.go:1120 +0x2c
2024-04-03T16:03:54.3081930Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.wsReader(0xc000014000, 0xc000801a20, 0xc000b22fc0, 0xc0029f4f00, 0xc0029f4f60)
2024-04-03T16:03:54.3082240Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:37 +0xf0
2024-04-03T16:03:54.3082640Z created by github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.initCleanServerAndWSClient in goroutine 15368
2024-04-03T16:03:54.3082960Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:88 +0x3a4
2024-04-03T16:03:54.3082960Z 
2024-04-03T16:03:54.3083040Z goroutine 5710 [runnable]:
2024-04-03T16:03:54.3083200Z sync.(*RWMutex).Unlock(0xc00051df28)
2024-04-03T16:03:54.3083480Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/sync/rwmutex.go:197 +0xe0
2024-04-03T16:03:54.3083940Z github.com/nspcc-dev/neo-go/pkg/rpcclient.(*WSClient).notifySubscribers(0xc00051ddc0, {0xbc?, {0x0?, 0x0?}})
2024-04-03T16:03:54.3084190Z 	/Users/runner/work/neo-go/neo-go/pkg/rpcclient/wsclient.go:706 +0x21c
2024-04-03T16:03:54.3084460Z github.com/nspcc-dev/neo-go/pkg/rpcclient.(*Internal).eventLoop(0xc00051ddc0)
2024-04-03T16:03:54.3084690Z 	/Users/runner/work/neo-go/neo-go/pkg/rpcclient/local.go:64 +0x3c
2024-04-03T16:03:54.3084980Z created by github.com/nspcc-dev/neo-go/pkg/rpcclient.NewInternal in goroutine 5705
2024-04-03T16:03:54.3085220Z 	/Users/runner/work/neo-go/neo-go/pkg/rpcclient/local.go:45 +0x2fc
2024-04-03T16:03:54.3085230Z 
2024-04-03T16:03:54.3085310Z goroutine 15376 [IO wait]:
2024-04-03T16:03:54.3085440Z internal/poll.runtime_pollWait(0x14fa86738, 0x72)
2024-04-03T16:03:54.3085690Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/runtime/netpoll.go:345 +0xa0
2024-04-03T16:03:54.3085830Z internal/poll.(*pollDesc).wait(0xc0020aefa0, 0x72, 0x0)
2024-04-03T16:03:54.3086130Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/internal/poll/fd_poll_runtime.go:84 +0xb8
2024-04-03T16:03:54.3086230Z internal/poll.(*pollDesc).waitRead(...)
2024-04-03T16:03:54.3086510Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/internal/poll/fd_poll_runtime.go:89
2024-04-03T16:03:54.3086700Z internal/poll.(*FD).Read(0xc0020aef80, {0xc001fb3000, 0x1000, 0x1000})
2024-04-03T16:03:54.3087010Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/internal/poll/fd_unix.go:164 +0x320
2024-04-03T16:03:54.3087170Z net.(*netFD).Read(0xc0020aef80, {0xc001fb3000, 0x1000, 0x1000})
2024-04-03T16:03:54.3087400Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/fd_posix.go:55 +0x48
2024-04-03T16:03:54.3087540Z net.(*conn).Read(0xc000196818, {0xc001fb3000, 0x1000, 0x1000})
2024-04-03T16:03:54.3087760Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/net.go:179 +0x88
2024-04-03T16:03:54.3087840Z bufio.(*Reader).fill(0xc0020a9380)
2024-04-03T16:03:54.3088080Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/bufio/bufio.go:110 +0x21c
2024-04-03T16:03:54.3088170Z bufio.(*Reader).Peek(0xc0020a9380, 0x2)
2024-04-03T16:03:54.3088400Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/bufio/bufio.go:148 +0xb4
2024-04-03T16:03:54.3088570Z github.com/gorilla/websocket.(*Conn).read(0xc00212dce0, 0x2)
2024-04-03T16:03:54.3088820Z 	/Users/runner/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/conn.go:378 +0x4c
2024-04-03T16:03:54.3089000Z github.com/gorilla/websocket.(*Conn).advanceFrame(0xc00212dce0)
2024-04-03T16:03:54.3089250Z 	/Users/runner/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/conn.go:824 +0xc4
2024-04-03T16:03:54.3089410Z github.com/gorilla/websocket.(*Conn).NextReader(0xc00212dce0)
2024-04-03T16:03:54.3089670Z 	/Users/runner/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/conn.go:1034 +0x1b8
2024-04-03T16:03:54.3089930Z github.com/gorilla/websocket.(*Conn).ReadJSON(0xc00212dce0, {0x1058c24e0, 0xc001225580})
2024-04-03T16:03:54.3090190Z 	/Users/runner/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/json.go:50 +0x34
2024-04-03T16:03:54.3090670Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).handleWsReads(0xc0002a1688, 0xc00212dce0, 0xc001fc39e0, 0xc0000149c0)
2024-04-03T16:03:54.3090940Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/server.go:739 +0x1d0
2024-04-03T16:03:54.3091440Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).handleHTTPRequest(0xc0002a1688, {0x105a171d8, 0xc00006aa80}, 0xc001ffe900)
2024-04-03T16:03:54.3091710Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/server.go:525 +0x8e0
2024-04-03T16:03:54.3091960Z net/http.HandlerFunc.ServeHTTP(0xc000149d20, {0x105a171d8, 0xc00006aa80}, 0xc001ffe900)
2024-04-03T16:03:54.3092220Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/http/server.go:2166 +0x4c
2024-04-03T16:03:54.3092540Z net/http.serverHandler.ServeHTTP({0xc002135350?}, {0x105a171d8, 0xc00006aa80}, 0xc001ffe900)
2024-04-03T16:03:54.3092820Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/http/server.go:3137 +0x29c
2024-04-03T16:03:54.3093020Z net/http.(*conn).serve(0xc0003877a0, {0x105a19548, 0xc002135140})
2024-04-03T16:03:54.3093270Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/http/server.go:2039 +0xf2c
2024-04-03T16:03:54.3093420Z created by net/http.(*Server).Serve in goroutine 15373
2024-04-03T16:03:54.3093670Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/http/server.go:3285 +0x678
2024-04-03T16:03:54.3093680Z 
2024-04-03T16:03:54.3093750Z goroutine 15118 [select]:
2024-04-03T16:03:54.3094030Z github.com/nspcc-dev/neo-go/pkg/network.(*Server).txHandlerLoop(0xc001e5d008)
2024-04-03T16:03:54.3094270Z 	/Users/runner/work/neo-go/neo-go/pkg/network/server.go:1155 +0x178
2024-04-03T16:03:54.3094570Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 15368
2024-04-03T16:03:54.3094810Z 	/Users/runner/work/neo-go/neo-go/pkg/network/server.go:291 +0x250
2024-04-03T16:03:54.3094810Z 
2024-04-03T16:03:54.3094890Z goroutine 15378 [select]:
2024-04-03T16:03:54.3095360Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).handleWsWrites(0xc0002a1688, 0xc00212dce0, 0xc001fc39e0, 0xc0020a9440)
2024-04-03T16:03:54.3095630Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/server.go:683 +0x104
2024-04-03T16:03:54.3096030Z created by github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).handleHTTPRequest in goroutine 15376
2024-04-03T16:03:54.3096300Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/server.go:524 +0x8cc
2024-04-03T16:03:54.3096330Z 
2024-04-03T16:03:54.3096410Z goroutine 15397 [select]:
2024-04-03T16:03:54.3096640Z github.com/nspcc-dev/neo-go/pkg/network.(*Server).run(0xc001e5d008)
2024-04-03T16:03:54.3096880Z 	/Users/runner/work/neo-go/neo-go/pkg/network/server.go:484 +0x66c
2024-04-03T16:03:54.3097170Z created by github.com/nspcc-dev/neo-go/pkg/network.(*Server).Start in goroutine 15368
2024-04-03T16:03:54.3097410Z 	/Users/runner/work/neo-go/neo-go/pkg/network/server.go:303 +0x654
2024-04-03T16:03:54.3097620Z FAIL	github.com/nspcc-dev/neo-go/pkg/services/rpcsrv	900.163s

From what I see, cleanup problem is not solved. wsReader is trying to read from WS connection:

2024-04-03T16:03:54.3076640Z goroutine 15115 [IO wait]:
2024-04-03T16:03:54.3076760Z internal/poll.runtime_pollWait(0x14fa6aac0, 0x72)
2024-04-03T16:03:54.3077010Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/runtime/netpoll.go:345 +0xa0
2024-04-03T16:03:54.3077150Z internal/poll.(*pollDesc).wait(0xc0020aef20, 0x72, 0x0)
2024-04-03T16:03:54.3077460Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/internal/poll/fd_poll_runtime.go:84 +0xb8
2024-04-03T16:03:54.3077550Z internal/poll.(*pollDesc).waitRead(...)
2024-04-03T16:03:54.3077870Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/internal/poll/fd_poll_runtime.go:89
2024-04-03T16:03:54.3078050Z internal/poll.(*FD).Read(0xc0020aef00, {0xc002004000, 0x1000, 0x1000})
2024-04-03T16:03:54.3078330Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/internal/poll/fd_unix.go:164 +0x320
2024-04-03T16:03:54.3078490Z net.(*netFD).Read(0xc0020aef00, {0xc002004000, 0x1000, 0x1000})
2024-04-03T16:03:54.3078720Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/fd_posix.go:55 +0x48
2024-04-03T16:03:54.3078880Z net.(*conn).Read(0xc000072568, {0xc002004000, 0x1000, 0x1000})
2024-04-03T16:03:54.3079090Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/net/net.go:179 +0x88
2024-04-03T16:03:54.3079180Z bufio.(*Reader).fill(0xc000b22f60)
2024-04-03T16:03:54.3079410Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/bufio/bufio.go:110 +0x21c
2024-04-03T16:03:54.3079500Z bufio.(*Reader).Peek(0xc000b22f60, 0x2)
2024-04-03T16:03:54.3079730Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/bufio/bufio.go:148 +0xb4
2024-04-03T16:03:54.3079890Z github.com/gorilla/websocket.(*Conn).read(0xc000801a20, 0x2)
2024-04-03T16:03:54.3080150Z 	/Users/runner/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/conn.go:378 +0x4c
2024-04-03T16:03:54.3080330Z github.com/gorilla/websocket.(*Conn).advanceFrame(0xc000801a20)
2024-04-03T16:03:54.3080590Z 	/Users/runner/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/conn.go:824 +0xc4
2024-04-03T16:03:54.3080760Z github.com/gorilla/websocket.(*Conn).NextReader(0xc000801a20)
2024-04-03T16:03:54.3081020Z 	/Users/runner/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/conn.go:1034 +0x1b8
2024-04-03T16:03:54.3081200Z github.com/gorilla/websocket.(*Conn).ReadMessage(0xc000801a20)
2024-04-03T16:03:54.3081450Z 	/Users/runner/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/conn.go:1120 +0x2c
2024-04-03T16:03:54.3081930Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.wsReader(0xc000014000, 0xc000801a20, 0xc000b22fc0, 0xc0029f4f00, 0xc0029f4f60)
2024-04-03T16:03:54.3082240Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:37 +0xf0
2024-04-03T16:03:54.3082640Z created by github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.initCleanServerAndWSClient in goroutine 15368
2024-04-03T16:03:54.3082960Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:88 +0x3a4

And cleanup routine from initCleanServerAndWSClient is waiting for wsReader to finish his work:

2024-04-03T16:03:54.3044450Z goroutine 15368 [chan receive]:
2024-04-03T16:03:54.3044750Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.initCleanServerAndWSClient.func1()
2024-04-03T16:03:54.3045060Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:102 +0x7c
2024-04-03T16:03:54.3045140Z testing.(*common).Cleanup.func1()
2024-04-03T16:03:54.3045380Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/testing/testing.go:1175 +0x148
2024-04-03T16:03:54.3045490Z testing.(*common).runCleanup(0xc000014000, 0x0)
2024-04-03T16:03:54.3045730Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/testing/testing.go:1353 +0x1ac
2024-04-03T16:03:54.3045800Z testing.tRunner.func2()
2024-04-03T16:03:54.3046040Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/testing/testing.go:1683 +0x4c
2024-04-03T16:03:54.3046130Z testing.tRunner(0xc000014000, 0x105a019d8)
2024-04-03T16:03:54.3046370Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/testing/testing.go:1695 +0x1ac
2024-04-03T16:03:54.3046460Z created by testing.(*T).Run in goroutine 1
2024-04-03T16:03:54.3046700Z 	/Users/runner/hostedtoolcache/go/1.22.1/arm64/src/testing/testing.go:1742 +0x5e8

We need to find out what is the reason of wsReader routine hanging on reading from WS connection: _, body, err := ws.ReadMessage() given the fact that we do set read deadline several lines above via err := ws.SetReadDeadline(time.Now().Add(5 * time.Second)).

@AnnaShaleva AnnaShaleva reopened this Apr 3, 2024
@AnnaShaleva
Copy link
Member Author

AnnaShaleva commented Apr 4, 2024 •
edited
Loading

A very similar error is discovered in #3397's Windows test failure in TestMaxSubscriptions. This test also uses initCleanServerAndWSClient helper, I suspect that this helper might be related to the root of the problem. This test also hangs on the same cleanup process.

2024-04-04T08:25:18.5775995Z === RUN   TestMaxSubscriptions
2024-04-04T08:25:18.5776712Z     logger.go:146: 2024-04-04T08:23:36.580Z	INFO	initial gas supply is not set or wrong, setting default value	{"InitialGASSupply": "52000000"}
2024-04-04T08:25:18.5777349Z     logger.go:146: 2024-04-04T08:23:36.580Z	INFO	MaxBlockSize is not set or wrong, setting default value	{"MaxBlockSize": 262144}
2024-04-04T08:25:18.5778063Z     logger.go:146: 2024-04-04T08:23:36.580Z	INFO	MaxBlockSystemFee is not set or wrong, setting default value	{"MaxBlockSystemFee": 900000000000}
2024-04-04T08:25:18.5778875Z     logger.go:146: 2024-04-04T08:23:36.580Z	INFO	MaxTransactionsPerBlock is not set or wrong, using default value	{"MaxTransactionsPerBlock": 512}
2024-04-04T08:25:18.5779737Z     logger.go:146: 2024-04-04T08:23:36.580Z	INFO	MaxValidUntilBlockIncrement is not set or wrong, using default value	{"MaxValidUntilBlockIncrement": 5760}
2024-04-04T08:25:18.5780199Z     logger.go:146: 2024-04-04T08:23:36.580Z	INFO	no storage version found! creating genesis block
2024-04-04T08:25:18.5780874Z     logger.go:146: 2024-04-04T08:23:36.590Z	INFO	ExtensiblePoolSize is not set or wrong, using default value	{"ExtensiblePoolSize": 20}
2024-04-04T08:25:18.5781519Z     logger.go:146: 2024-04-04T08:23:36.590Z	INFO	SessionPoolSize is not set or wrong, setting default value	{"SessionPoolSize": 20}
2024-04-04T08:25:18.5782249Z     logger.go:146: 2024-04-04T08:23:36.590Z	INFO	MaxIteratorResultItems is not set or wrong, setting default value	{"MaxIteratorResultItems": 100}
2024-04-04T08:25:18.5782925Z     logger.go:146: 2024-04-04T08:23:36.590Z	INFO	MaxFindResultItems is not set or wrong, setting default value	{"MaxFindResultItems": 100}
2024-04-04T08:25:18.5783569Z     logger.go:146: 2024-04-04T08:23:36.590Z	INFO	MaxNEP11Tokens is not set or wrong, setting default value	{"MaxNEP11Tokens": 100}
2024-04-04T08:25:18.5784281Z     logger.go:146: 2024-04-04T08:23:36.590Z	INFO	MaxRequestBodyBytes is not set or wong, setting default value	{"MaxRequestBodyBytes": 5242880}
2024-04-04T08:25:18.5785010Z     logger.go:146: 2024-04-04T08:23:36.590Z	INFO	MaxRequestHeaderBytes is not set or wong, setting default value	{"MaxRequestHeaderBytes": 1048576}
2024-04-04T08:25:18.5785734Z     logger.go:146: 2024-04-04T08:23:36.590Z	INFO	MaxWebSocketClients is not set or wrong, setting default value	{"MaxWebSocketClients": 64}
2024-04-04T08:25:18.5786191Z     logger.go:146: 2024-04-04T08:23:36.590Z	INFO	starting rpc-server	{"endpoint": "127.0.0.1:0"}
2024-04-04T08:25:18.5786788Z     logger.go:146: 2024-04-04T08:23:37.145Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2024-04-04T08:25:18.5787382Z     logger.go:146: 2024-04-04T08:23:37.381Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2024-04-04T08:25:18.5787959Z     logger.go:146: 2024-04-04T08:23:37.586Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2024-04-04T08:25:18.5788663Z     logger.go:146: 2024-04-04T08:23:37.758Z	INFO	persisted to disk	{"blocks": 0, "keys": 127, "headerHeight": 0, "blockHeight": 0, "took": "224µs"}
2024-04-04T08:25:18.5789255Z     logger.go:146: 2024-04-04T08:23:37.899Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2024-04-04T08:25:18.5789842Z     logger.go:146: 2024-04-04T08:23:38.088Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2024-04-04T08:25:18.5790461Z     logger.go:146: 2024-04-04T08:23:38.183Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2024-04-04T08:25:18.5791033Z     logger.go:146: 2024-04-04T08:23:38.341Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2024-04-04T08:25:18.5791611Z     logger.go:146: 2024-04-04T08:23:38.655Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2024-04-04T08:25:18.5792179Z     logger.go:146: 2024-04-04T08:23:38.828Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2024-04-04T08:25:18.5792749Z     logger.go:146: 2024-04-04T08:23:38.937Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2024-04-04T08:25:18.5793317Z     logger.go:146: 2024-04-04T08:23:39.267Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2024-04-04T08:25:18.5793894Z     logger.go:146: 2024-04-04T08:23:39.519Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2024-04-04T08:25:18.5794499Z     logger.go:146: 2024-04-04T08:23:39.723Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2024-04-04T08:25:18.5795137Z     logger.go:146: 2024-04-04T08:23:39.912Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2024-04-04T08:25:18.5795705Z     logger.go:146: 2024-04-04T08:23:40.116Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2024-04-04T08:25:18.5796270Z     logger.go:146: 2024-04-04T08:23:40.290Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2024-04-04T08:25:18.5796839Z     logger.go:146: 2024-04-04T08:23:40.478Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[block_added]"}
2024-04-04T08:25:18.5797849Z     logger.go:146: 2024-04-04T08:23:40.478Z	ERROR	Error encountered with rpc request	{"code": -32603, "cause": "maximum number of subscriptions is reached", "method": "subscribe", "params": "[block_added]"}
2024-04-04T08:25:18.5797965Z panic: test timed out after 15m0s
2024-04-04T08:25:18.5798050Z running tests:
2024-04-04T08:25:18.5798167Z 	TestMaxSubscriptions (5s)
2024-04-04T08:25:18.5798179Z 
2024-04-04T08:25:18.5798272Z goroutine 12987 [running]:
2024-04-04T08:25:18.5798378Z testing.(*M).startAlarm.func1()
2024-04-04T08:25:18.5798671Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:2366 +0x265
2024-04-04T08:25:18.5798763Z created by time.goFunc
2024-04-04T08:25:18.5799016Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/time/sleep.go:177 +0x45
2024-04-04T08:25:18.5799022Z 
2024-04-04T08:25:18.5799117Z goroutine 1 [chan receive]:
2024-04-04T08:25:18.5799313Z testing.(*T).Run(0xc0004261a0, {0x141569273, 0x14}, 0x141688878)
2024-04-04T08:25:18.5799584Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:1750 +0x851
2024-04-04T08:25:18.5799740Z testing.runTests.func1(0xc0004261a0)
2024-04-04T08:25:18.5800013Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:2161 +0x86
2024-04-04T08:25:18.5800135Z testing.tRunner(0xc0004261a0, 0xc00021db10)
2024-04-04T08:25:18.5800411Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:1689 +0x21f
2024-04-04T08:25:18.5800768Z testing.runTests(0xc000400120, {0x1412d67e0, 0x31, 0x31}, {0xc00021dbb8?, 0xc00021dc00?, 0x1421230e0?})
2024-04-04T08:25:18.5801045Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:2159 +0x8bf
2024-04-04T08:25:18.5801140Z testing.(*M).Run(0xc00042e000)
2024-04-04T08:25:18.5801407Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:2027 +0xf18
2024-04-04T08:25:18.5801484Z main.main()
2024-04-04T08:25:18.5801586Z 	_testmain.go:145 +0x2be
2024-04-04T08:25:18.5801592Z 
2024-04-04T08:25:18.5801688Z goroutine 14265 [IO wait]:
2024-04-04T08:25:18.5801837Z internal/poll.runtime_pollWait(0x478c81e8, 0x72)
2024-04-04T08:25:18.5802113Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/runtime/netpoll.go:345 +0x85
2024-04-04T08:25:18.5802284Z internal/poll.(*pollDesc).wait(0xc0003b4940, 0x72, 0x0)
2024-04-04T08:25:18.5802625Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_poll_runtime.go:84 +0xb1
2024-04-04T08:25:18.5802770Z internal/poll.execIO(0xc0003b47a0, 0x141689738)
2024-04-04T08:25:18.5803084Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:175 +0x271
2024-04-04T08:25:18.5803316Z internal/poll.(*FD).Read(0xc0003b4788, {0xc000ad4000, 0x1000, 0x1000})
2024-04-04T08:25:18.5803641Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:436 +0x488
2024-04-04T08:25:18.5803832Z net.(*netFD).Read(0xc0003b4788, {0xc000ad4000, 0x1000, 0x1000})
2024-04-04T08:25:18.5804072Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/fd_posix.go:55 +0x4b
2024-04-04T08:25:18.5804262Z net.(*conn).Read(0xc00029e540, {0xc000ad4000, 0x1000, 0x1000})
2024-04-04T08:25:18.5804497Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/net.go:179 +0xad
2024-04-04T08:25:18.5804603Z bufio.(*Reader).fill(0xc000eabc80)
2024-04-04T08:25:18.5804858Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/bufio/bufio.go:110 +0x2b0
2024-04-04T08:25:18.5805005Z bufio.(*Reader).Peek(0xc000eabc80, 0x2)
2024-04-04T08:25:18.5805314Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/bufio/bufio.go:148 +0xc7
2024-04-04T08:25:18.5805517Z github.com/gorilla/websocket.(*Conn).read(0xc000ed11e0, 0x2)
2024-04-04T08:25:18.5805863Z 	C:/Users/runneradmin/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/conn.go:378 +0x5b
2024-04-04T08:25:18.5806079Z github.com/gorilla/websocket.(*Conn).advanceFrame(0xc000ed11e0)
2024-04-04T08:25:18.5806424Z 	C:/Users/runneradmin/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/conn.go:824 +0x125
2024-04-04T08:25:18.5806628Z github.com/gorilla/websocket.(*Conn).NextReader(0xc000ed11e0)
2024-04-04T08:25:18.5806977Z 	C:/Users/runneradmin/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/conn.go:1034 +0x291
2024-04-04T08:25:18.5807187Z github.com/gorilla/websocket.(*Conn).ReadMessage(0xc000ed11e0)
2024-04-04T08:25:18.5807520Z 	C:/Users/runneradmin/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/conn.go:1120 +0x2f
2024-04-04T08:25:18.5808115Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.wsReader(0xc0001716c0, 0xc000ed11e0, 0xc000eabce0, 0xc000c77da0, 0xc000c77e00)
2024-04-04T08:25:18.5808436Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:38 +0x147
2024-04-04T08:25:18.5808937Z created by github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.initCleanServerAndWSClient in goroutine 14366
2024-04-04T08:25:18.5809245Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:89 +0x479
2024-04-04T08:25:18.5809252Z 
2024-04-04T08:25:18.5809349Z goroutine 4922 [runnable]:
2024-04-04T08:25:18.5809462Z sync/atomic.(*Value).Load(0xc00052f7d8)
2024-04-04T08:25:18.5809736Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/sync/atomic/value.go:29 +0x45
2024-04-04T08:25:18.5809887Z context.(*cancelCtx).Done(0xc00052f7c0)
2024-04-04T08:25:18.5810161Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/context/context.go:439 +0x50
2024-04-04T08:25:18.5810511Z github.com/nspcc-dev/neo-go/pkg/rpcclient.(*Internal).eventLoop(0xc00060e380)
2024-04-04T08:25:18.5810724Z 	D:/a/neo-go/neo-go/pkg/rpcclient/local.go:55 +0x73
2024-04-04T08:25:18.5811091Z created by github.com/nspcc-dev/neo-go/pkg/rpcclient.NewInternal in goroutine 5001
2024-04-04T08:25:18.5811309Z 	D:/a/neo-go/neo-go/pkg/rpcclient/local.go:45 +0x3cd
2024-04-04T08:25:18.5811316Z 
2024-04-04T08:25:18.5811412Z goroutine 14366 [chan receive]:
2024-04-04T08:25:18.5811799Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.initCleanServerAndWSClient.func1()
2024-04-04T08:25:18.5812108Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:103 +0x85
2024-04-04T08:25:18.5812217Z testing.(*common).Cleanup.func1()
2024-04-04T08:25:18.5812491Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:1175 +0x17a
2024-04-04T08:25:18.5812632Z testing.(*common).runCleanup(0xc0001716c0, 0x0)
2024-04-04T08:25:18.5812910Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:1353 +0x262
2024-04-04T08:25:18.5813004Z testing.tRunner.func2()
2024-04-04T08:25:18.5813274Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:1683 +0x51
2024-04-04T08:25:18.5813396Z testing.tRunner(0xc0001716c0, 0x141688878)
2024-04-04T08:25:18.5813673Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:1695 +0x25e
2024-04-04T08:25:18.5813796Z created by testing.(*T).Run in goroutine 1
2024-04-04T08:25:18.5814055Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/testing/testing.go:1742 +0x826
2024-04-04T08:25:18.5814061Z 
2024-04-04T08:25:18.5814156Z goroutine 5060 [runnable]:
2024-04-04T08:25:18.5814265Z sync/atomic.(*Value).Load(0xc000918f18)
2024-04-04T08:25:18.5814527Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/sync/atomic/value.go:36 +0x93
2024-04-04T08:25:18.5814635Z context.(*cancelCtx).Done(0xc000918f00)
2024-04-04T08:25:18.5814907Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/context/context.go:439 +0x50
2024-04-04T08:25:18.5815242Z github.com/nspcc-dev/neo-go/pkg/rpcclient.(*Internal).eventLoop(0xc0008bc540)
2024-04-04T08:25:18.5815448Z 	D:/a/neo-go/neo-go/pkg/rpcclient/local.go:55 +0x73
2024-04-04T08:25:18.5815852Z created by github.com/nspcc-dev/neo-go/pkg/rpcclient.NewInternal in goroutine 5040
2024-04-04T08:25:18.5816129Z 	D:/a/neo-go/neo-go/pkg/rpcclient/local.go:45 +0x3cd
2024-04-04T08:25:18.5816135Z 
2024-04-04T08:25:18.5816229Z goroutine 14369 [select]:
2024-04-04T08:25:18.5816611Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).handleSubEvents(0xc00009ac88)
2024-04-04T08:25:18.5816873Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/server.go:2925 +0x86d
2024-04-04T08:25:18.5817285Z created by github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).Start in goroutine 14366
2024-04-04T08:25:18.5817537Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/server.go:390 +0xf4
2024-04-04T08:25:18.5817545Z 
2024-04-04T08:25:18.5817647Z goroutine 14373 [IO wait]:
2024-04-04T08:25:18.5817806Z internal/poll.runtime_pollWait(0x478c7ff8, 0x72)
2024-04-04T08:25:18.5818079Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/runtime/netpoll.go:345 +0x85
2024-04-04T08:25:18.5818248Z internal/poll.(*pollDesc).wait(0xc0003b4bc0, 0x72, 0x0)
2024-04-04T08:25:18.5818594Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_poll_runtime.go:84 +0xb1
2024-04-04T08:25:18.5818729Z internal/poll.execIO(0xc0003b4a20, 0x141689738)
2024-04-04T08:25:18.5819043Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:175 +0x271
2024-04-04T08:25:18.5819269Z internal/poll.(*FD).Read(0xc0003b4a08, {0xc000ef6000, 0x1000, 0x1000})
2024-04-04T08:25:18.5819581Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:436 +0x488
2024-04-04T08:25:18.5819772Z net.(*netFD).Read(0xc0003b4a08, {0xc000ef6000, 0x1000, 0x1000})
2024-04-04T08:25:18.5820051Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/fd_posix.go:55 +0x4b
2024-04-04T08:25:18.5820237Z net.(*conn).Read(0xc000432670, {0xc000ef6000, 0x1000, 0x1000})
2024-04-04T08:25:18.5820465Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/net.go:179 +0xad
2024-04-04T08:25:18.5820569Z bufio.(*Reader).fill(0xc000e5f4a0)
2024-04-04T08:25:18.5820819Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/bufio/bufio.go:110 +0x2b0
2024-04-04T08:25:18.5820934Z bufio.(*Reader).Peek(0xc000e5f4a0, 0x2)
2024-04-04T08:25:18.5821181Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/bufio/bufio.go:148 +0xc7
2024-04-04T08:25:18.5821381Z github.com/gorilla/websocket.(*Conn).read(0xc000ef42c0, 0x2)
2024-04-04T08:25:18.5821721Z 	C:/Users/runneradmin/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/conn.go:378 +0x5b
2024-04-04T08:25:18.5821934Z github.com/gorilla/websocket.(*Conn).advanceFrame(0xc000ef42c0)
2024-04-04T08:25:18.5822273Z 	C:/Users/runneradmin/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/conn.go:824 +0x125
2024-04-04T08:25:18.5822473Z github.com/gorilla/websocket.(*Conn).NextReader(0xc000ef42c0)
2024-04-04T08:25:18.5822820Z 	C:/Users/runneradmin/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/conn.go:1034 +0x291
2024-04-04T08:25:18.5823130Z github.com/gorilla/websocket.(*Conn).ReadJSON(0xc000ef42c0, {0x1414182c0, 0xc0012cd7c0})
2024-04-04T08:25:18.5823464Z 	C:/Users/runneradmin/go/pkg/mod/github.com/gorilla/websocket@v1.5.1/json.go:50 +0x35
2024-04-04T08:25:18.5824063Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).handleWsReads(0xc00009ac88, 0xc000ef42c0, 0xc000e99f20, 0xc000ef21a0)
2024-04-04T08:25:18.5824319Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/server.go:739 +0x252
2024-04-04T08:25:18.5824931Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).handleHTTPRequest(0xc00009ac88, {0x14186ad50, 0xc000df1dc0}, 0xc000e45200)
2024-04-04T08:25:18.5825179Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/server.go:525 +0xb91
2024-04-04T08:25:18.5825488Z net/http.HandlerFunc.ServeHTTP(0xc00285f930, {0x14186ad50, 0xc000df1dc0}, 0xc000e45200)
2024-04-04T08:25:18.5825762Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/http/server.go:2166 +0x48
2024-04-04T08:25:18.5826093Z net/http.serverHandler.ServeHTTP({0xc000ee4900?}, {0x14186ad50, 0xc000df1dc0}, 0xc000e45200)
2024-04-04T08:25:18.5826411Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/http/server.go:3137 +0x2a2
2024-04-04T08:25:18.5826676Z net/http.(*conn).serve(0xc000d3aab0, {0x14186cfc0, 0xc000ee45d0})
2024-04-04T08:25:18.5826960Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/http/server.go:2039 +0x13c5
2024-04-04T08:25:18.5827129Z created by net/http.(*Server).Serve in goroutine 14371
2024-04-04T08:25:18.5827397Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/http/server.go:3285 +0x8ed
2024-04-04T08:25:18.5827403Z 
2024-04-04T08:25:18.5827496Z goroutine 4728 [runnable]:
2024-04-04T08:25:18.5827603Z sync/atomic.(*Value).Load(0xc000bb0d38)
2024-04-04T08:25:18.5827879Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/sync/atomic/value.go:36 +0x93
2024-04-04T08:25:18.5827988Z context.(*cancelCtx).Done(0xc000bb0d20)
2024-04-04T08:25:18.5828259Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/context/context.go:439 +0x50
2024-04-04T08:25:18.5828600Z github.com/nspcc-dev/neo-go/pkg/rpcclient.(*Internal).eventLoop(0xc000692700)
2024-04-04T08:25:18.5828813Z 	D:/a/neo-go/neo-go/pkg/rpcclient/local.go:55 +0x73
2024-04-04T08:25:18.5829177Z created by github.com/nspcc-dev/neo-go/pkg/rpcclient.NewInternal in goroutine 4722
2024-04-04T08:25:18.5829388Z 	D:/a/neo-go/neo-go/pkg/rpcclient/local.go:45 +0x3cd
2024-04-04T08:25:18.5829398Z 
2024-04-04T08:25:18.5829489Z goroutine 14371 [IO wait]:
2024-04-04T08:25:18.5829631Z internal/poll.runtime_pollWait(0x488d9c10, 0x72)
2024-04-04T08:25:18.5829902Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/runtime/netpoll.go:345 +0x85
2024-04-04T08:25:18.5830068Z internal/poll.(*pollDesc).wait(0xc0003b46c0, 0x72, 0x0)
2024-04-04T08:25:18.5830405Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_poll_runtime.go:84 +0xb1
2024-04-04T08:25:18.5830578Z internal/poll.execIO(0xc0003b4520, 0xc000e2d9f8)
2024-04-04T08:25:18.5830898Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:175 +0x271
2024-04-04T08:25:18.5831211Z internal/poll.(*FD).acceptOne(0xc0003b4508, 0x3c4, {0xc000910a50, 0x2, 0x2}, 0xc0003b4520)
2024-04-04T08:25:18.5831526Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:944 +0xf8
2024-04-04T08:25:18.5831693Z internal/poll.(*FD).Accept(0xc0003b4508, 0xc000e2dc70)
2024-04-04T08:25:18.5832004Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:978 +0x3cb
2024-04-04T08:25:18.5832109Z net.(*netFD).accept(0xc0003b4508)
2024-04-04T08:25:18.5832367Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/fd_windows.go:178 +0x85
2024-04-04T08:25:18.5832482Z net.(*TCPListener).accept(0xc000ea8740)
2024-04-04T08:25:18.5832752Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/tcpsock_posix.go:159 +0x3e
2024-04-04T08:25:18.5832864Z net.(*TCPListener).Accept(0xc000ea8740)
2024-04-04T08:25:18.5833112Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/tcpsock.go:327 +0x65
2024-04-04T08:25:18.5833325Z net/http.(*Server).Serve(0xc0008d73b0, {0x14186af60, 0xc000ea8740})
2024-04-04T08:25:18.5833607Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/http/server.go:3255 +0x672
2024-04-04T08:25:18.5833738Z net/http/httptest.(*Server).goServe.func1()
2024-04-04T08:25:18.5834051Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/http/httptest/server.go:310 +0xbc
2024-04-04T08:25:18.5834275Z created by net/http/httptest.(*Server).goServe in goroutine 14366
2024-04-04T08:25:18.5834588Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/http/httptest/server.go:308 +0xa6
2024-04-04T08:25:18.5834594Z 
2024-04-04T08:25:18.5834698Z goroutine 14368 [select]:
2024-04-04T08:25:18.5834992Z github.com/nspcc-dev/neo-go/pkg/core.(*Blockchain).Run(0xc000619208)
2024-04-04T08:25:18.5835219Z 	D:/a/neo-go/neo-go/pkg/core/blockchain.go:1074 +0x2dc
2024-04-04T08:25:18.5835759Z created by github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.getUnitTestChainWithCustomConfig in goroutine 14366
2024-04-04T08:25:18.5836077Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/server_helper_test.go:85 +0x737
2024-04-04T08:25:18.5836083Z 
2024-04-04T08:25:18.5836175Z goroutine 5775 [runnable]:
2024-04-04T08:25:18.5836320Z sync/atomic.(*Value).Load(0xc000bb19b8)
2024-04-04T08:25:18.5836665Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/sync/atomic/value.go:28 +0xf9
2024-04-04T08:25:18.5836770Z context.(*cancelCtx).Done(0xc000bb19a0)
2024-04-04T08:25:18.5837038Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/context/context.go:439 +0x50
2024-04-04T08:25:18.5837374Z github.com/nspcc-dev/neo-go/pkg/rpcclient.(*Internal).eventLoop(0xc00060fa40)
2024-04-04T08:25:18.5837584Z 	D:/a/neo-go/neo-go/pkg/rpcclient/local.go:55 +0x73
2024-04-04T08:25:18.5837942Z created by github.com/nspcc-dev/neo-go/pkg/rpcclient.NewInternal in goroutine 5770
2024-04-04T08:25:18.5838155Z 	D:/a/neo-go/neo-go/pkg/rpcclient/local.go:45 +0x3cd
2024-04-04T08:25:18.5838164Z 
2024-04-04T08:25:18.5838254Z goroutine 14370 [IO wait]:
2024-04-04T08:25:18.5838395Z internal/poll.runtime_pollWait(0x48481918, 0x72)
2024-04-04T08:25:18.5838664Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/runtime/netpoll.go:345 +0x85
2024-04-04T08:25:18.5838833Z internal/poll.(*pollDesc).wait(0xc0003b4440, 0x72, 0x0)
2024-04-04T08:25:18.5839169Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_poll_runtime.go:84 +0xb1
2024-04-04T08:25:18.5839307Z internal/poll.execIO(0xc0003b42a0, 0xc000c35930)
2024-04-04T08:25:18.5839620Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:175 +0x271
2024-04-04T08:25:18.5839915Z internal/poll.(*FD).acceptOne(0xc0003b4288, 0x2c0, {0xc000910960, 0x2, 0x2}, 0xc0003b42a0)
2024-04-04T08:25:18.5840225Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:944 +0xf8
2024-04-04T08:25:18.5840386Z internal/poll.(*FD).Accept(0xc0003b4288, 0xc000c35ba8)
2024-04-04T08:25:18.5840736Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/internal/poll/fd_windows.go:978 +0x3cb
2024-04-04T08:25:18.5840841Z net.(*netFD).accept(0xc0003b4288)
2024-04-04T08:25:18.5841101Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/fd_windows.go:178 +0x85
2024-04-04T08:25:18.5841214Z net.(*TCPListener).accept(0xc000ea8720)
2024-04-04T08:25:18.5841490Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/tcpsock_posix.go:159 +0x3e
2024-04-04T08:25:18.5841597Z net.(*TCPListener).Accept(0xc000ea8720)
2024-04-04T08:25:18.5841843Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/tcpsock.go:327 +0x65
2024-04-04T08:25:18.5842052Z net/http.(*Server).Serve(0xc0008d72c0, {0x14186af60, 0xc000ea8720})
2024-04-04T08:25:18.5842325Z 	C:/hostedtoolcache/windows/go/1.22.1/x64/src/net/http/server.go:3255 +0x672
2024-04-04T08:25:18.5842696Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).Start.func1(0xc0008d72c0)
2024-04-04T08:25:18.5842947Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/server.go:403 +0x79
2024-04-04T08:25:18.5843362Z created by github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).Start in goroutine 14366
2024-04-04T08:25:18.5843614Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/server.go:402 +0x1c5
2024-04-04T08:25:18.5843622Z 
2024-04-04T08:25:18.5843716Z goroutine 14375 [select]:
2024-04-04T08:25:18.5844303Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).handleWsWrites(0xc00009ac88, 0xc000ef42c0, 0xc000e99f20, 0xc000e5f560)
2024-04-04T08:25:18.5844561Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/server.go:683 +0x197
2024-04-04T08:25:18.5845037Z created by github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).handleHTTPRequest in goroutine 14373
2024-04-04T08:25:18.5845291Z 	D:/a/neo-go/neo-go/pkg/services/rpcsrv/server.go:524 +0xb6c
2024-04-04T08:25:18.5845297Z 
2024-04-04T08:25:18.5845386Z goroutine 14372 [select]:
2024-04-04T08:25:18.5845768Z github.com/nspcc-dev/neo-go/pkg/core.(*Blockchain).notificationDispatcher(0xc000619208)
2024-04-04T08:25:18.5845994Z 	D:/a/neo-go/neo-go/pkg/core/blockchain.go:1336 +0x4b6
2024-04-04T08:25:18.5846355Z created by github.com/nspcc-dev/neo-go/pkg/core.(*Blockchain).Run in goroutine 14368
2024-04-04T08:25:18.5846577Z 	D:/a/neo-go/neo-go/pkg/core/blockchain.go:1071 +0x18b
2024-04-04T08:25:18.5846869Z FAIL	github.com/nspcc-dev/neo-go/pkg/services/rpcsrv	900.330s

@AnnaShaleva AnnaShaleva mentioned this issue Apr 4, 2024
Merged
AnnaShaleva added a commit that referenced this issue Apr 4, 2024
@AnnaShaleva
rpcsrv: enforce WS connection close on cleanup
fc3e9dc 
Do not wait until wsReader routine gracefully finishes its work before
WS connection close. Instead, firstly close the connection, and after
that wait for proper wsReader exit.

It's a harsh way, but I don't have any other options to try, because
wsReader routine hangs on `ws.ReadMessage()` operation for more than
ReadDeadline (more than 5 seconds) during test cleanup which results in
the test timeout.

Close #3378.

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: enforce WS connection close on cleanup
a1ca8ab 
Do not wait until wsReader routine gracefully finishes its work before
WS connection close. Instead, firstly close the connection, and after
that wait for proper wsReader exit.

It's a harsh way, but I don't have any other options to try, because
wsReader routine hangs on `ws.ReadMessage()` operation for more than
ReadDeadline (more than 5 seconds) during test cleanup which results in
the test timeout.

Close #3378.

Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
AnnaShaleva added a commit that referenced this issue Apr 4, 2024
@AnnaShaleva
rpcsrv: enforce WS connection close on test cleanup
e5c919f 
Do not wait until wsReader routine gracefully finishes its work before
WS connection close. Instead, firstly close the connection, and after
that wait for proper wsReader exit.

It's a harsh way, but I don't have any other options to try, because
wsReader routine hangs on `ws.ReadMessage()` operation for more than
ReadDeadline (more than 5 seconds) during test cleanup which results in
the test timeout.

Close #3378.

Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
@AnnaShaleva AnnaShaleva mentioned this issue Apr 4, 2024
Closed
@AnnaShaleva AnnaShaleva changed the title TestFilteredNotaryRequestSubscriptions fails on Windows WS-based RPC server tests fail on Windows Apr 4, 2024
@AnnaShaleva
Copy link
Member Author

So the group of tests is affected, not only TestFilteredNotaryRequestSubscriptions, but also TestMaxSubscriptions (reproduced on workflow run) and likely other WS-related RPC server tests.

@AnnaShaleva AnnaShaleva mentioned this issue May 17, 2024
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@AnnaShaleva AnnaShaleva

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
2 participants
@AnnaShaleva @AliceInHunterland