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

rpcsrv: fix TestFailedPreconditionShutdown shutdown #3335

Merged
merged 2 commits into from Mar 6, 2024
Merged

rpcsrv: fix TestFailedPreconditionShutdown shutdown #3335

merged 2 commits into from Mar 6, 2024

Conversation

AliceInHunterland
Copy link
Contributor

@AliceInHunterland AliceInHunterland commented Mar 4, 2024 •
edited

Close #3217

@codecov Codecov
Copy link

codecov bot commented Mar 4, 2024 •
edited

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 84.87%. Comparing base (8d67f17) to head (de5cb18).
Report is 18 commits behind head on master.

❗ Current head de5cb18 differs from pull request most recent head ee39b5c. Consider uploading reports for the commit ee39b5c to get more accurate results

Additional details and impacted files 
@@           Coverage Diff           @@
##           master    #3335   +/-   ##
=======================================
  Coverage   84.87%   84.87%           
=======================================
  Files         328      328           
  Lines       44835    44835           
=======================================
+ Hits        38052    38055    +3     
+ Misses       5270     5268    -2     
+ Partials     1513     1512    -1

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

@AliceInHunterland
Copy link
Contributor Author

AliceInHunterland commented Mar 4, 2024 •
edited

hm https://github.com/nspcc-dev/neo-go/actions/runs/8144019284/job/22257197349?pr=3335#logs

2024-03-04T17:14:48.8779100Z === RUN   TestFilteredNotaryRequestSubscriptions
2024-03-04T17:14:48.8780280Z     logger.go:130: 2024-03-04T17:04:02.459Z	INFO	initial gas supply is not set or wrong, setting default value	{"InitialGASSupply": "52000000"}
2024-03-04T17:14:48.8781300Z     logger.go:130: 2024-03-04T17:04:02.459Z	INFO	MaxBlockSize is not set or wrong, setting default value	{"MaxBlockSize": 262144}
2024-03-04T17:14:48.8782570Z     logger.go:130: 2024-03-04T17:04:02.460Z	INFO	MaxBlockSystemFee is not set or wrong, setting default value	{"MaxBlockSystemFee": 900000000000}
2024-03-04T17:14:48.8783970Z     logger.go:130: 2024-03-04T17:04:02.460Z	INFO	MaxTransactionsPerBlock is not set or wrong, using default value	{"MaxTransactionsPerBlock": 512}
2024-03-04T17:14:48.8785270Z     logger.go:130: 2024-03-04T17:04:02.460Z	INFO	MaxValidUntilBlockIncrement is not set or wrong, using default value	{"MaxValidUntilBlockIncrement": 5760}
2024-03-04T17:14:48.8786000Z     logger.go:130: 2024-03-04T17:04:02.474Z	INFO	no storage version found! creating genesis block
2024-03-04T17:14:48.8787100Z     logger.go:130: 2024-03-04T17:04:02.481Z	INFO	ExtensiblePoolSize is not set or wrong, using default value	{"ExtensiblePoolSize": 20}
2024-03-04T17:14:48.8788150Z     logger.go:130: 2024-03-04T17:04:02.481Z	INFO	SessionPoolSize is not set or wrong, setting default value	{"SessionPoolSize": 20}
2024-03-04T17:14:48.8789340Z     logger.go:130: 2024-03-04T17:04:02.481Z	INFO	MaxIteratorResultItems is not set or wrong, setting default value	{"MaxIteratorResultItems": 100}
2024-03-04T17:14:48.8790590Z     logger.go:130: 2024-03-04T17:04:02.481Z	INFO	MaxFindResultItems is not set or wrong, setting default value	{"MaxFindResultItems": 100}
2024-03-04T17:14:48.8791620Z     logger.go:130: 2024-03-04T17:04:02.481Z	INFO	MaxNEP11Tokens is not set or wrong, setting default value	{"MaxNEP11Tokens": 100}
2024-03-04T17:14:48.8792780Z     logger.go:130: 2024-03-04T17:04:02.481Z	INFO	MaxRequestBodyBytes is not set or wong, setting default value	{"MaxRequestBodyBytes": 5242880}
2024-03-04T17:14:48.8793980Z     logger.go:130: 2024-03-04T17:04:02.481Z	INFO	MaxRequestHeaderBytes is not set or wong, setting default value	{"MaxRequestHeaderBytes": 1048576}
2024-03-04T17:14:48.8795130Z     logger.go:130: 2024-03-04T17:04:02.482Z	INFO	MaxWebSocketClients is not set or wrong, setting default value	{"MaxWebSocketClients": 64}
2024-03-04T17:14:48.8795840Z     logger.go:130: 2024-03-04T17:04:02.482Z	INFO	starting rpc-server	{"endpoint": "127.0.0.1:0"}
2024-03-04T17:14:48.8796600Z     logger.go:130: 2024-03-04T17:04:02.674Z	INFO	node started	{"blockHeight": 0, "headerHeight": 0}
2024-03-04T17:14:48.8797330Z     logger.go:130: 2024-03-04T17:04:02.674Z	INFO	node reached synchronized state, starting services
2024-03-04T17:14:48.8798370Z     logger.go:130: 2024-03-04T17:04:02.862Z	DEBUG	done processing headers	{"headerIndex": 1, "blockHeight": 0, "took": "70.418493ms"}
2024-03-04T17:14:48.8799410Z     logger.go:130: 2024-03-04T17:04:02.965Z	DEBUG	done processing headers	{"headerIndex": 2, "blockHeight": 1, "took": "865.422µs"}
2024-03-04T17:14:48.8800440Z     logger.go:130: 2024-03-04T17:04:02.969Z	DEBUG	done processing headers	{"headerIndex": 3, "blockHeight": 2, "took": "943.987µs"}
2024-03-04T17:14:48.8801580Z     logger.go:130: 2024-03-04T17:04:02.972Z	DEBUG	done processing headers	{"headerIndex": 4, "blockHeight": 3, "took": "710.744µs"}
2024-03-04T17:14:48.8802630Z     logger.go:130: 2024-03-04T17:04:02.995Z	DEBUG	done processing headers	{"headerIndex": 5, "blockHeight": 4, "took": "703.643µs"}
2024-03-04T17:14:48.8804850Z     logger.go:130: 2024-03-04T17:04:02.997Z	INFO	bad notification	{"contract": "565cff9508ebc75aadd7fe59f38dac610ab6093c", "event": "Transfer", "error": "notification Transfer is invalid: parameter 0 type mismatch: Hash160 (manifest) vs ByteString (notification)"}
2024-03-04T17:14:48.8805880Z     logger.go:130: 2024-03-04T17:04:03.000Z	DEBUG	done processing headers	{"headerIndex": 6, "blockHeight": 5, "took": "1.162408ms"}
2024-03-04T17:14:48.8807020Z     logger.go:130: 2024-03-04T17:04:03.005Z	DEBUG	done processing headers	{"headerIndex": 7, "blockHeight": 6, "took": "1.648468ms"}
2024-03-04T17:14:48.8808060Z     logger.go:130: 2024-03-04T17:04:03.008Z	DEBUG	done processing headers	{"headerIndex": 8, "blockHeight": 7, "took": "714.789µs"}
2024-03-04T17:14:48.8809100Z     logger.go:130: 2024-03-04T17:04:03.010Z	DEBUG	done processing headers	{"headerIndex": 9, "blockHeight": 8, "took": "730.162µs"}
2024-03-04T17:14:48.8810130Z     logger.go:130: 2024-03-04T17:04:03.081Z	DEBUG	done processing headers	{"headerIndex": 10, "blockHeight": 9, "took": "942.499µs"}
2024-03-04T17:14:48.8811320Z     logger.go:130: 2024-03-04T17:04:03.086Z	DEBUG	done processing headers	{"headerIndex": 11, "blockHeight": 10, "took": "1.089595ms"}
2024-03-04T17:14:48.8812360Z     logger.go:130: 2024-03-04T17:04:03.358Z	DEBUG	done processing headers	{"headerIndex": 12, "blockHeight": 11, "took": "13.29073ms"}
2024-03-04T17:14:48.8813550Z     logger.go:130: 2024-03-04T17:04:03.530Z	INFO	persisted to disk	{"blocks": 11, "keys": 438, "headerHeight": 12, "blockHeight": 11, "took": "21.816995ms"}
2024-03-04T17:14:48.8814590Z     logger.go:130: 2024-03-04T17:04:03.556Z	DEBUG	done processing headers	{"headerIndex": 13, "blockHeight": 12, "took": "24.71533ms"}
2024-03-04T17:14:48.8815650Z     logger.go:130: 2024-03-04T17:04:03.650Z	DEBUG	done processing headers	{"headerIndex": 14, "blockHeight": 13, "took": "22.205158ms"}
2024-03-04T17:14:48.8816690Z     logger.go:130: 2024-03-04T17:04:03.780Z	DEBUG	done processing headers	{"headerIndex": 15, "blockHeight": 14, "took": "754.942µs"}
2024-03-04T17:14:48.8818400Z     logger.go:130: 2024-03-04T17:04:03.790Z	DEBUG	done processing headers	{"headerIndex": 16, "blockHeight": 15, "took": "1.087414ms"}
2024-03-04T17:14:48.8819890Z     logger.go:130: 2024-03-04T17:04:03.795Z	DEBUG	done processing headers	{"headerIndex": 17, "blockHeight": 16, "took": "645.864µs"}
2024-03-04T17:14:48.8821830Z     logger.go:130: 2024-03-04T17:04:03.801Z	DEBUG	done processing headers	{"headerIndex": 18, "blockHeight": 17, "took": "1.250881ms"}
2024-03-04T17:14:48.8822060Z     subscription_test.go:36: 
2024-03-04T17:14:48.8822910Z         	Error Trace:	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:36
2024-03-04T17:14:48.8823740Z         	            				/Users/runner/hostedtoolcache/go/1.21.7/x64/src/runtime/asm_amd64.s:1650
2024-03-04T17:14:48.8824030Z         	Error:      	Received unexpected error:
2024-03-04T17:14:48.8824650Z         	            	read tcp 127.0.0.1:51059->127.0.0.1:51058: i/o timeout
2024-03-04T17:14:48.8825020Z         	Test:       	TestFilteredNotaryRequestSubscriptions
2024-03-04T17:14:48.8826110Z     logger.go:130: 2024-03-04T17:04:03.920Z	DEBUG	done processing headers	{"headerIndex": 19, "blockHeight": 18, "took": "725.706µs"}
2024-03-04T17:14:48.8827150Z     logger.go:130: 2024-03-04T17:04:03.923Z	DEBUG	done processing headers	{"headerIndex": 20, "blockHeight": 19, "took": "755.266µs"}
2024-03-04T17:14:48.8828280Z     logger.go:130: 2024-03-04T17:04:03.926Z	DEBUG	done processing headers	{"headerIndex": 21, "blockHeight": 20, "took": "672.855µs"}
2024-03-04T17:14:48.8829440Z     logger.go:130: 2024-03-04T17:04:03.929Z	DEBUG	done processing headers	{"headerIndex": 22, "blockHeight": 21, "took": "686.697µs"}
2024-03-04T17:14:48.8830860Z     logger.go:130: 2024-03-04T17:04:03.967Z	DEBUG	done processing headers	{"headerIndex": 23, "blockHeight": 22, "took": "22.948823ms"}
2024-03-04T17:14:48.8832630Z     logger.go:130: 2024-03-04T17:04:03.968Z	WARN	contract invocation failed	{"tx": "82279bfe9bada282ca0f8cb8e0bb124b921af36f00c69a518320322c6f4fef60", "block": 23, "error": "at instruction 0 (ABORT): ABORT"}
2024-03-04T17:14:48.8833000Z === RUN   TestFilteredNotaryRequestSubscriptions/matching_signer
2024-03-04T17:14:48.8833260Z === NAME  TestFilteredNotaryRequestSubscriptions
2024-03-04T17:14:48.8834310Z     logger.go:130: 2024-03-04T17:04:03.994Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[notary_request_event ]"}
2024-03-04T17:14:48.8835670Z     logger.go:130: 2024-03-04T17:04:04.586Z	INFO	persisted to disk	{"blocks": 12, "keys": 867, "headerHeight": 23, "blockHeight": 23, "took": "847.439µs"}
2024-03-04T17:14:48.8835860Z panic: test timed out after 10m0s
2024-03-04T17:14:48.8836010Z running tests:
2024-03-04T17:14:48.8836290Z 	TestFilteredNotaryRequestSubscriptions (8m40s)
2024-03-04T17:14:48.8836670Z 	TestFilteredNotaryRequestSubscriptions/matching_signer (8m39s)
2024-03-04T17:14:48.8836690Z 
2024-03-04T17:14:48.8837010Z goroutine 13212 [running]:
2024-03-04T17:14:48.8837170Z testing.(*M).startAlarm.func1()
2024-03-04T17:14:48.8837680Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/testing/testing.go:2259 +0x259
2024-03-04T17:14:48.8837830Z created by time.goFunc
2024-03-04T17:14:48.8838270Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/time/sleep.go:176 +0x45
2024-03-04T17:14:48.8838280Z 
2024-03-04T17:14:48.8838460Z goroutine 1 [chan receive, 8 minutes]:
2024-03-04T17:14:48.8838740Z testing.(*T).Run(0xc00020c680, {0x240fa27, 0x26}, 0x252b8d8)
2024-03-04T17:14:48.8839240Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/testing/testing.go:1649 +0x871
2024-03-04T17:14:48.8839410Z testing.runTests.func1(0x0?)
2024-03-04T17:14:48.8839890Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/testing/testing.go:2054 +0x85
2024-03-04T17:14:48.8840080Z testing.tRunner(0xc00020c680, 0xc0002adaf8)
2024-03-04T17:14:48.8840570Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/testing/testing.go:1595 +0x262
2024-03-04T17:14:48.8841180Z testing.runTests(0xc00022c140?, {0x2fb0600, 0x31, 0x31}, {0x1c?, 0x1e?, 0x2fbc6c0?})
2024-03-04T17:14:48.8841660Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/testing/testing.go:2052 +0x8ae
2024-03-04T17:14:48.8841820Z testing.(*M).Run(0xc00022c140)
2024-03-04T17:14:48.8842310Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/testing/testing.go:1925 +0xcd8
2024-03-04T17:14:48.8842450Z main.main()
2024-03-04T17:14:48.8842610Z 	_testmain.go:145 +0x2be
2024-03-04T17:14:48.8842620Z 
2024-03-04T17:14:48.8842800Z goroutine 8092 [select, 9 minutes]:
2024-03-04T17:14:48.8843450Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).handleSubEvents(0xc016b5f680)
2024-03-04T17:14:48.8843980Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/server.go:2921 +0x86d
2024-03-04T17:14:48.8844660Z created by github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).Start in goroutine 8089
2024-03-04T17:14:48.8845160Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/server.go:391 +0xf4
2024-03-04T17:14:48.8845170Z 
2024-03-04T17:14:48.8845350Z goroutine 697 [IO wait, 9 minutes]:
2024-03-04T17:14:48.8845580Z internal/poll.runtime_pollWait(0x4d3ff880, 0x72)
2024-03-04T17:14:48.8846070Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/runtime/netpoll.go:343 +0x85
2024-03-04T17:14:48.8846390Z internal/poll.(*pollDesc).wait(0xc0018487a0, 0xc000ef5000?, 0x0)
2024-03-04T17:14:48.8846990Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_poll_runtime.go:84 +0xb1
2024-03-04T17:14:48.8847180Z internal/poll.(*pollDesc).waitRead(...)
2024-03-04T17:14:48.8847720Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_poll_runtime.go:89
2024-03-04T17:14:48.8848090Z internal/poll.(*FD).Read(0xc001848780, {0xc000ef5000, 0x1000, 0x1000})
2024-03-04T17:14:48.8848760Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_unix.go:164 +0x405
2024-03-04T17:14:48.8849080Z net.(*netFD).Read(0xc001848780, {0xc000ef5000, 0x1000, 0x1000})
2024-03-04T17:14:48.8849530Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/fd_posix.go:55 +0x4b
2024-03-04T17:14:48.8849890Z net.(*conn).Read(0xc00014ca68, {0xc000ef5000, 0x1000, 0x1000})
2024-03-04T17:14:48.8850370Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/net.go:179 +0xad
2024-03-04T17:14:48.8850750Z net/http.(*connReader).Read(0xc001850120, {0xc000ef5000, 0x1000, 0x1000})
2024-03-04T17:14:48.8851240Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/server.go:791 +0x2b2
2024-03-04T17:14:48.8851400Z bufio.(*Reader).fill(0xc001852300)
2024-03-04T17:14:48.8852020Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/bufio/bufio.go:113 +0x29a
2024-03-04T17:14:48.8852210Z bufio.(*Reader).Peek(0xc001852300, 0x4)
2024-03-04T17:14:48.8852670Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/bufio/bufio.go:151 +0xc7
2024-03-04T17:14:48.8852980Z net/http.(*conn).serve(0xc00047eea0, {0x27096f0, 0xc000eb53e0})
2024-03-04T17:14:48.8853470Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/server.go:2044 +0xe7c
2024-03-04T17:14:48.8853860Z created by net/http.(*Server).Serve in goroutine 613
2024-03-04T17:14:48.8854350Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/server.go:3086 +0x86d
2024-03-04T17:14:48.8854350Z 
2024-03-04T17:14:48.8854540Z goroutine 393 [IO wait, 9 minutes]:
2024-03-04T17:14:48.8854770Z internal/poll.runtime_pollWait(0x4d3ffe50, 0x72)
2024-03-04T17:14:48.8855250Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/runtime/netpoll.go:343 +0x85
2024-03-04T17:14:48.8855580Z internal/poll.(*pollDesc).wait(0xc000f1d8a0, 0xc0016f2000?, 0x0)
2024-03-04T17:14:48.8856170Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_poll_runtime.go:84 +0xb1
2024-03-04T17:14:48.8856360Z internal/poll.(*pollDesc).waitRead(...)
2024-03-04T17:14:48.8856890Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_poll_runtime.go:89
2024-03-04T17:14:48.8857250Z internal/poll.(*FD).Read(0xc000f1d880, {0xc0016f2000, 0x1000, 0x1000})
2024-03-04T17:14:48.8857780Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_unix.go:164 +0x405
2024-03-04T17:14:48.8858180Z net.(*netFD).Read(0xc000f1d880, {0xc0016f2000, 0x1000, 0x1000})
2024-03-04T17:14:48.8858620Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/fd_posix.go:55 +0x4b
2024-03-04T17:14:48.8858910Z net.(*conn).Read(0xc00014c2a0, {0xc0016f2000, 0x1000, 0x1000})
2024-03-04T17:14:48.8859310Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/net.go:179 +0xad
2024-03-04T17:14:48.8859690Z net/http.(*connReader).Read(0xc0016e4a20, {0xc0016f2000, 0x1000, 0x1000})
2024-03-04T17:14:48.8860170Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/server.go:791 +0x2b2
2024-03-04T17:14:48.8860330Z bufio.(*Reader).fill(0xc00169dda0)
2024-03-04T17:14:48.8860780Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/bufio/bufio.go:113 +0x29a
2024-03-04T17:14:48.8860960Z bufio.(*Reader).Peek(0xc00169dda0, 0x4)
2024-03-04T17:14:48.8861390Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/bufio/bufio.go:151 +0xc7
2024-03-04T17:14:48.8861700Z net/http.(*conn).serve(0xc000d38e10, {0x27096f0, 0xc0003840c0})
2024-03-04T17:14:48.8862180Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/server.go:2044 +0xe7c
2024-03-04T17:14:48.8862450Z created by net/http.(*Server).Serve in goroutine 274
2024-03-04T17:14:48.8862930Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/server.go:3086 +0x86d
2024-03-04T17:14:48.8862940Z 
2024-03-04T17:14:48.8863110Z goroutine 613 [IO wait, 9 minutes]:
2024-03-04T17:14:48.8863340Z internal/poll.runtime_pollWait(0x4d3ffa70, 0x72)
2024-03-04T17:14:48.8863820Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/runtime/netpoll.go:343 +0x85
2024-03-04T17:14:48.8864130Z internal/poll.(*pollDesc).wait(0xc000e809a0, 0x10c9d01?, 0x0)
2024-03-04T17:14:48.8864820Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_poll_runtime.go:84 +0xb1
2024-03-04T17:14:48.8865020Z internal/poll.(*pollDesc).waitRead(...)
2024-03-04T17:14:48.8865560Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_poll_runtime.go:89
2024-03-04T17:14:48.8865750Z internal/poll.(*FD).Accept(0xc000e80980)
2024-03-04T17:14:48.8866280Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_unix.go:611 +0x425
2024-03-04T17:14:48.8866440Z net.(*netFD).accept(0xc000e80980)
2024-03-04T17:14:48.8866870Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/fd_unix.go:172 +0x3e
2024-03-04T17:14:48.8867050Z net.(*TCPListener).accept(0xc001fce9c0)
2024-03-04T17:14:48.8867540Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/tcpsock_posix.go:152 +0x3e
2024-03-04T17:14:48.8867810Z net.(*TCPListener).Accept(0xc001fce9c0)
2024-03-04T17:14:48.8868260Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/tcpsock.go:315 +0x65
2024-03-04T17:14:48.8868580Z net/http.(*Server).Serve(0xc000dcc1e0, {0x27072b0, 0xc001fce9c0})
2024-03-04T17:14:48.8869070Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/server.go:3056 +0x5e8
2024-03-04T17:14:48.8869280Z net/http/httptest.(*Server).goServe.func1()
2024-03-04T17:14:48.8869820Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/httptest/server.go:310 +0xd0
2024-03-04T17:14:48.8870280Z created by net/http/httptest.(*Server).goServe in goroutine 592
2024-03-04T17:14:48.8870820Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/httptest/server.go:308 +0xa6
2024-03-04T17:14:48.8870830Z 
2024-03-04T17:14:48.8871010Z goroutine 133 [IO wait, 9 minutes]:
2024-03-04T17:14:48.8871230Z internal/poll.runtime_pollWait(0x4d400328, 0x72)
2024-03-04T17:14:48.8871710Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/runtime/netpoll.go:343 +0x85
2024-03-04T17:14:48.8872050Z internal/poll.(*pollDesc).wait(0xc0001a4420, 0xc000081a01?, 0x0)
2024-03-04T17:14:48.8872630Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_poll_runtime.go:84 +0xb1
2024-03-04T17:14:48.8872830Z internal/poll.(*pollDesc).waitRead(...)
2024-03-04T17:14:48.8873360Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_poll_runtime.go:89
2024-03-04T17:14:48.8873560Z internal/poll.(*FD).Accept(0xc0001a4400)
2024-03-04T17:14:48.8874180Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_unix.go:611 +0x425
2024-03-04T17:14:48.8874350Z net.(*netFD).accept(0xc0001a4400)
2024-03-04T17:14:48.8874780Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/fd_unix.go:172 +0x3e
2024-03-04T17:14:48.8874960Z net.(*TCPListener).accept(0xc00018f480)
2024-03-04T17:14:48.8875450Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/tcpsock_posix.go:152 +0x3e
2024-03-04T17:14:48.8875630Z net.(*TCPListener).Accept(0xc00018f480)
2024-03-04T17:14:48.8876070Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/tcpsock.go:315 +0x65
2024-03-04T17:14:48.8876390Z net/http.(*Server).Serve(0xc0000ac0f0, {0x27072b0, 0xc00018f480})
2024-03-04T17:14:48.8876880Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/server.go:3056 +0x5e8
2024-03-04T17:14:48.8877090Z net/http/httptest.(*Server).goServe.func1()
2024-03-04T17:14:48.8877640Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/httptest/server.go:310 +0xd0
2024-03-04T17:14:48.8878000Z created by net/http/httptest.(*Server).goServe in goroutine 101
2024-03-04T17:14:48.8878540Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/httptest/server.go:308 +0xa6
2024-03-04T17:14:48.8878550Z 
2024-03-04T17:14:48.8878730Z goroutine 11213 [select, 8 minutes]:
2024-03-04T17:14:48.8879450Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).handleSubEvents(0xc004991180)
2024-03-04T17:14:48.8879980Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/server.go:2921 +0x86d
2024-03-04T17:14:48.8880670Z created by github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).Start in goroutine 11210
2024-03-04T17:14:48.8881180Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/server.go:391 +0xf4
2024-03-04T17:14:48.8881190Z hm
2024-03-04T17:14:48.8779100Z === RUN   TestFilteredNotaryRequestSubscriptions
2024-03-04T17:14:48.8780280Z     logger.go:130: 2024-03-04T17:04:02.459Z	INFO	initial gas supply is not set or wrong, setting default value	{"InitialGASSupply": "52000000"}
2024-03-04T17:14:48.8781300Z     logger.go:130: 2024-03-04T17:04:02.459Z	INFO	MaxBlockSize is not set or wrong, setting default value	{"MaxBlockSize": 262144}
2024-03-04T17:14:48.8782570Z     logger.go:130: 2024-03-04T17:04:02.460Z	INFO	MaxBlockSystemFee is not set or wrong, setting default value	{"MaxBlockSystemFee": 900000000000}
2024-03-04T17:14:48.8783970Z     logger.go:130: 2024-03-04T17:04:02.460Z	INFO	MaxTransactionsPerBlock is not set or wrong, using default value	{"MaxTransactionsPerBlock": 512}
2024-03-04T17:14:48.8785270Z     logger.go:130: 2024-03-04T17:04:02.460Z	INFO	MaxValidUntilBlockIncrement is not set or wrong, using default value	{"MaxValidUntilBlockIncrement": 5760}
2024-03-04T17:14:48.8786000Z     logger.go:130: 2024-03-04T17:04:02.474Z	INFO	no storage version found! creating genesis block
2024-03-04T17:14:48.8787100Z     logger.go:130: 2024-03-04T17:04:02.481Z	INFO	ExtensiblePoolSize is not set or wrong, using default value	{"ExtensiblePoolSize": 20}
2024-03-04T17:14:48.8788150Z     logger.go:130: 2024-03-04T17:04:02.481Z	INFO	SessionPoolSize is not set or wrong, setting default value	{"SessionPoolSize": 20}
2024-03-04T17:14:48.8789340Z     logger.go:130: 2024-03-04T17:04:02.481Z	INFO	MaxIteratorResultItems is not set or wrong, setting default value	{"MaxIteratorResultItems": 100}
2024-03-04T17:14:48.8790590Z     logger.go:130: 2024-03-04T17:04:02.481Z	INFO	MaxFindResultItems is not set or wrong, setting default value	{"MaxFindResultItems": 100}
2024-03-04T17:14:48.8791620Z     logger.go:130: 2024-03-04T17:04:02.481Z	INFO	MaxNEP11Tokens is not set or wrong, setting default value	{"MaxNEP11Tokens": 100}
2024-03-04T17:14:48.8792780Z     logger.go:130: 2024-03-04T17:04:02.481Z	INFO	MaxRequestBodyBytes is not set or wong, setting default value	{"MaxRequestBodyBytes": 5242880}
2024-03-04T17:14:48.8793980Z     logger.go:130: 2024-03-04T17:04:02.481Z	INFO	MaxRequestHeaderBytes is not set or wong, setting default value	{"MaxRequestHeaderBytes": 1048576}
2024-03-04T17:14:48.8795130Z     logger.go:130: 2024-03-04T17:04:02.482Z	INFO	MaxWebSocketClients is not set or wrong, setting default value	{"MaxWebSocketClients": 64}
2024-03-04T17:14:48.8795840Z     logger.go:130: 2024-03-04T17:04:02.482Z	INFO	starting rpc-server	{"endpoint": "127.0.0.1:0"}
2024-03-04T17:14:48.8796600Z     logger.go:130: 2024-03-04T17:04:02.674Z	INFO	node started	{"blockHeight": 0, "headerHeight": 0}
2024-03-04T17:14:48.8797330Z     logger.go:130: 2024-03-04T17:04:02.674Z	INFO	node reached synchronized state, starting services
2024-03-04T17:14:48.8798370Z     logger.go:130: 2024-03-04T17:04:02.862Z	DEBUG	done processing headers	{"headerIndex": 1, "blockHeight": 0, "took": "70.418493ms"}
2024-03-04T17:14:48.8799410Z     logger.go:130: 2024-03-04T17:04:02.965Z	DEBUG	done processing headers	{"headerIndex": 2, "blockHeight": 1, "took": "865.422µs"}
2024-03-04T17:14:48.8800440Z     logger.go:130: 2024-03-04T17:04:02.969Z	DEBUG	done processing headers	{"headerIndex": 3, "blockHeight": 2, "took": "943.987µs"}
2024-03-04T17:14:48.8801580Z     logger.go:130: 2024-03-04T17:04:02.972Z	DEBUG	done processing headers	{"headerIndex": 4, "blockHeight": 3, "took": "710.744µs"}
2024-03-04T17:14:48.8802630Z     logger.go:130: 2024-03-04T17:04:02.995Z	DEBUG	done processing headers	{"headerIndex": 5, "blockHeight": 4, "took": "703.643µs"}
2024-03-04T17:14:48.8804850Z     logger.go:130: 2024-03-04T17:04:02.997Z	INFO	bad notification	{"contract": "565cff9508ebc75aadd7fe59f38dac610ab6093c", "event": "Transfer", "error": "notification Transfer is invalid: parameter 0 type mismatch: Hash160 (manifest) vs ByteString (notification)"}
2024-03-04T17:14:48.8805880Z     logger.go:130: 2024-03-04T17:04:03.000Z	DEBUG	done processing headers	{"headerIndex": 6, "blockHeight": 5, "took": "1.162408ms"}
2024-03-04T17:14:48.8807020Z     logger.go:130: 2024-03-04T17:04:03.005Z	DEBUG	done processing headers	{"headerIndex": 7, "blockHeight": 6, "took": "1.648468ms"}
2024-03-04T17:14:48.8808060Z     logger.go:130: 2024-03-04T17:04:03.008Z	DEBUG	done processing headers	{"headerIndex": 8, "blockHeight": 7, "took": "714.789µs"}
2024-03-04T17:14:48.8809100Z     logger.go:130: 2024-03-04T17:04:03.010Z	DEBUG	done processing headers	{"headerIndex": 9, "blockHeight": 8, "took": "730.162µs"}
2024-03-04T17:14:48.8810130Z     logger.go:130: 2024-03-04T17:04:03.081Z	DEBUG	done processing headers	{"headerIndex": 10, "blockHeight": 9, "took": "942.499µs"}
2024-03-04T17:14:48.8811320Z     logger.go:130: 2024-03-04T17:04:03.086Z	DEBUG	done processing headers	{"headerIndex": 11, "blockHeight": 10, "took": "1.089595ms"}
2024-03-04T17:14:48.8812360Z     logger.go:130: 2024-03-04T17:04:03.358Z	DEBUG	done processing headers	{"headerIndex": 12, "blockHeight": 11, "took": "13.29073ms"}
2024-03-04T17:14:48.8813550Z     logger.go:130: 2024-03-04T17:04:03.530Z	INFO	persisted to disk	{"blocks": 11, "keys": 438, "headerHeight": 12, "blockHeight": 11, "took": "21.816995ms"}
2024-03-04T17:14:48.8814590Z     logger.go:130: 2024-03-04T17:04:03.556Z	DEBUG	done processing headers	{"headerIndex": 13, "blockHeight": 12, "took": "24.71533ms"}
2024-03-04T17:14:48.8815650Z     logger.go:130: 2024-03-04T17:04:03.650Z	DEBUG	done processing headers	{"headerIndex": 14, "blockHeight": 13, "took": "22.205158ms"}
2024-03-04T17:14:48.8816690Z     logger.go:130: 2024-03-04T17:04:03.780Z	DEBUG	done processing headers	{"headerIndex": 15, "blockHeight": 14, "took": "754.942µs"}
2024-03-04T17:14:48.8818400Z     logger.go:130: 2024-03-04T17:04:03.790Z	DEBUG	done processing headers	{"headerIndex": 16, "blockHeight": 15, "took": "1.087414ms"}
2024-03-04T17:14:48.8819890Z     logger.go:130: 2024-03-04T17:04:03.795Z	DEBUG	done processing headers	{"headerIndex": 17, "blockHeight": 16, "took": "645.864µs"}
2024-03-04T17:14:48.8821830Z     logger.go:130: 2024-03-04T17:04:03.801Z	DEBUG	done processing headers	{"headerIndex": 18, "blockHeight": 17, "took": "1.250881ms"}
2024-03-04T17:14:48.8822060Z     subscription_test.go:36: 
2024-03-04T17:14:48.8822910Z         	Error Trace:	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:36
2024-03-04T17:14:48.8823740Z         	            				/Users/runner/hostedtoolcache/go/1.21.7/x64/src/runtime/asm_amd64.s:1650
2024-03-04T17:14:48.8824030Z         	Error:      	Received unexpected error:
2024-03-04T17:14:48.8824650Z         	            	read tcp 127.0.0.1:51059->127.0.0.1:51058: i/o timeout
2024-03-04T17:14:48.8825020Z         	Test:       	TestFilteredNotaryRequestSubscriptions
2024-03-04T17:14:48.8826110Z     logger.go:130: 2024-03-04T17:04:03.920Z	DEBUG	done processing headers	{"headerIndex": 19, "blockHeight": 18, "took": "725.706µs"}
2024-03-04T17:14:48.8827150Z     logger.go:130: 2024-03-04T17:04:03.923Z	DEBUG	done processing headers	{"headerIndex": 20, "blockHeight": 19, "took": "755.266µs"}
2024-03-04T17:14:48.8828280Z     logger.go:130: 2024-03-04T17:04:03.926Z	DEBUG	done processing headers	{"headerIndex": 21, "blockHeight": 20, "took": "672.855µs"}
2024-03-04T17:14:48.8829440Z     logger.go:130: 2024-03-04T17:04:03.929Z	DEBUG	done processing headers	{"headerIndex": 22, "blockHeight": 21, "took": "686.697µs"}
2024-03-04T17:14:48.8830860Z     logger.go:130: 2024-03-04T17:04:03.967Z	DEBUG	done processing headers	{"headerIndex": 23, "blockHeight": 22, "took": "22.948823ms"}
2024-03-04T17:14:48.8832630Z     logger.go:130: 2024-03-04T17:04:03.968Z	WARN	contract invocation failed	{"tx": "82279bfe9bada282ca0f8cb8e0bb124b921af36f00c69a518320322c6f4fef60", "block": 23, "error": "at instruction 0 (ABORT): ABORT"}
2024-03-04T17:14:48.8833000Z === RUN   TestFilteredNotaryRequestSubscriptions/matching_signer
2024-03-04T17:14:48.8833260Z === NAME  TestFilteredNotaryRequestSubscriptions
2024-03-04T17:14:48.8834310Z     logger.go:130: 2024-03-04T17:04:03.994Z	DEBUG	processing rpc request	{"method": "subscribe", "params": "[notary_request_event ]"}
2024-03-04T17:14:48.8835670Z     logger.go:130: 2024-03-04T17:04:04.586Z	INFO	persisted to disk	{"blocks": 12, "keys": 867, "headerHeight": 23, "blockHeight": 23, "took": "847.439µs"}
2024-03-04T17:14:48.8835860Z panic: test timed out after 10m0s
2024-03-04T17:14:48.8836010Z running tests:
2024-03-04T17:14:48.8836290Z 	TestFilteredNotaryRequestSubscriptions (8m40s)
2024-03-04T17:14:48.8836670Z 	TestFilteredNotaryRequestSubscriptions/matching_signer (8m39s)
2024-03-04T17:14:48.8836690Z 
2024-03-04T17:14:48.8837010Z goroutine 13212 [running]:
2024-03-04T17:14:48.8837170Z testing.(*M).startAlarm.func1()
2024-03-04T17:14:48.8837680Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/testing/testing.go:2259 +0x259
2024-03-04T17:14:48.8837830Z created by time.goFunc
2024-03-04T17:14:48.8838270Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/time/sleep.go:176 +0x45
2024-03-04T17:14:48.8838280Z 
2024-03-04T17:14:48.8838460Z goroutine 1 [chan receive, 8 minutes]:
2024-03-04T17:14:48.8838740Z testing.(*T).Run(0xc00020c680, {0x240fa27, 0x26}, 0x252b8d8)
2024-03-04T17:14:48.8839240Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/testing/testing.go:1649 +0x871
2024-03-04T17:14:48.8839410Z testing.runTests.func1(0x0?)
2024-03-04T17:14:48.8839890Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/testing/testing.go:2054 +0x85
2024-03-04T17:14:48.8840080Z testing.tRunner(0xc00020c680, 0xc0002adaf8)
2024-03-04T17:14:48.8840570Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/testing/testing.go:1595 +0x262
2024-03-04T17:14:48.8841180Z testing.runTests(0xc00022c140?, {0x2fb0600, 0x31, 0x31}, {0x1c?, 0x1e?, 0x2fbc6c0?})
2024-03-04T17:14:48.8841660Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/testing/testing.go:2052 +0x8ae
2024-03-04T17:14:48.8841820Z testing.(*M).Run(0xc00022c140)
2024-03-04T17:14:48.8842310Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/testing/testing.go:1925 +0xcd8
2024-03-04T17:14:48.8842450Z main.main()
2024-03-04T17:14:48.8842610Z 	_testmain.go:145 +0x2be
2024-03-04T17:14:48.8842620Z 
2024-03-04T17:14:48.8842800Z goroutine 8092 [select, 9 minutes]:
2024-03-04T17:14:48.8843450Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).handleSubEvents(0xc016b5f680)
2024-03-04T17:14:48.8843980Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/server.go:2921 +0x86d
2024-03-04T17:14:48.8844660Z created by github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).Start in goroutine 8089
2024-03-04T17:14:48.8845160Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/server.go:391 +0xf4
2024-03-04T17:14:48.8845170Z 
2024-03-04T17:14:48.8845350Z goroutine 697 [IO wait, 9 minutes]:
2024-03-04T17:14:48.8845580Z internal/poll.runtime_pollWait(0x4d3ff880, 0x72)
2024-03-04T17:14:48.8846070Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/runtime/netpoll.go:343 +0x85
2024-03-04T17:14:48.8846390Z internal/poll.(*pollDesc).wait(0xc0018487a0, 0xc000ef5000?, 0x0)
2024-03-04T17:14:48.8846990Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_poll_runtime.go:84 +0xb1
2024-03-04T17:14:48.8847180Z internal/poll.(*pollDesc).waitRead(...)
2024-03-04T17:14:48.8847720Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_poll_runtime.go:89
2024-03-04T17:14:48.8848090Z internal/poll.(*FD).Read(0xc001848780, {0xc000ef5000, 0x1000, 0x1000})
2024-03-04T17:14:48.8848760Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_unix.go:164 +0x405
2024-03-04T17:14:48.8849080Z net.(*netFD).Read(0xc001848780, {0xc000ef5000, 0x1000, 0x1000})
2024-03-04T17:14:48.8849530Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/fd_posix.go:55 +0x4b
2024-03-04T17:14:48.8849890Z net.(*conn).Read(0xc00014ca68, {0xc000ef5000, 0x1000, 0x1000})
2024-03-04T17:14:48.8850370Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/net.go:179 +0xad
2024-03-04T17:14:48.8850750Z net/http.(*connReader).Read(0xc001850120, {0xc000ef5000, 0x1000, 0x1000})
2024-03-04T17:14:48.8851240Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/server.go:791 +0x2b2
2024-03-04T17:14:48.8851400Z bufio.(*Reader).fill(0xc001852300)
2024-03-04T17:14:48.8852020Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/bufio/bufio.go:113 +0x29a
2024-03-04T17:14:48.8852210Z bufio.(*Reader).Peek(0xc001852300, 0x4)
2024-03-04T17:14:48.8852670Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/bufio/bufio.go:151 +0xc7
2024-03-04T17:14:48.8852980Z net/http.(*conn).serve(0xc00047eea0, {0x27096f0, 0xc000eb53e0})
2024-03-04T17:14:48.8853470Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/server.go:2044 +0xe7c
2024-03-04T17:14:48.8853860Z created by net/http.(*Server).Serve in goroutine 613
2024-03-04T17:14:48.8854350Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/server.go:3086 +0x86d
2024-03-04T17:14:48.8854350Z 
2024-03-04T17:14:48.8854540Z goroutine 393 [IO wait, 9 minutes]:
2024-03-04T17:14:48.8854770Z internal/poll.runtime_pollWait(0x4d3ffe50, 0x72)
2024-03-04T17:14:48.8855250Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/runtime/netpoll.go:343 +0x85
2024-03-04T17:14:48.8855580Z internal/poll.(*pollDesc).wait(0xc000f1d8a0, 0xc0016f2000?, 0x0)
2024-03-04T17:14:48.8856170Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_poll_runtime.go:84 +0xb1
2024-03-04T17:14:48.8856360Z internal/poll.(*pollDesc).waitRead(...)
2024-03-04T17:14:48.8856890Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_poll_runtime.go:89
2024-03-04T17:14:48.8857250Z internal/poll.(*FD).Read(0xc000f1d880, {0xc0016f2000, 0x1000, 0x1000})
2024-03-04T17:14:48.8857780Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_unix.go:164 +0x405
2024-03-04T17:14:48.8858180Z net.(*netFD).Read(0xc000f1d880, {0xc0016f2000, 0x1000, 0x1000})
2024-03-04T17:14:48.8858620Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/fd_posix.go:55 +0x4b
2024-03-04T17:14:48.8858910Z net.(*conn).Read(0xc00014c2a0, {0xc0016f2000, 0x1000, 0x1000})
2024-03-04T17:14:48.8859310Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/net.go:179 +0xad
2024-03-04T17:14:48.8859690Z net/http.(*connReader).Read(0xc0016e4a20, {0xc0016f2000, 0x1000, 0x1000})
2024-03-04T17:14:48.8860170Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/server.go:791 +0x2b2
2024-03-04T17:14:48.8860330Z bufio.(*Reader).fill(0xc00169dda0)
2024-03-04T17:14:48.8860780Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/bufio/bufio.go:113 +0x29a
2024-03-04T17:14:48.8860960Z bufio.(*Reader).Peek(0xc00169dda0, 0x4)
2024-03-04T17:14:48.8861390Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/bufio/bufio.go:151 +0xc7
2024-03-04T17:14:48.8861700Z net/http.(*conn).serve(0xc000d38e10, {0x27096f0, 0xc0003840c0})
2024-03-04T17:14:48.8862180Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/server.go:2044 +0xe7c
2024-03-04T17:14:48.8862450Z created by net/http.(*Server).Serve in goroutine 274
2024-03-04T17:14:48.8862930Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/server.go:3086 +0x86d
2024-03-04T17:14:48.8862940Z 
2024-03-04T17:14:48.8863110Z goroutine 613 [IO wait, 9 minutes]:
2024-03-04T17:14:48.8863340Z internal/poll.runtime_pollWait(0x4d3ffa70, 0x72)
2024-03-04T17:14:48.8863820Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/runtime/netpoll.go:343 +0x85
2024-03-04T17:14:48.8864130Z internal/poll.(*pollDesc).wait(0xc000e809a0, 0x10c9d01?, 0x0)
2024-03-04T17:14:48.8864820Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_poll_runtime.go:84 +0xb1
2024-03-04T17:14:48.8865020Z internal/poll.(*pollDesc).waitRead(...)
2024-03-04T17:14:48.8865560Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_poll_runtime.go:89
2024-03-04T17:14:48.8865750Z internal/poll.(*FD).Accept(0xc000e80980)
2024-03-04T17:14:48.8866280Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_unix.go:611 +0x425
2024-03-04T17:14:48.8866440Z net.(*netFD).accept(0xc000e80980)
2024-03-04T17:14:48.8866870Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/fd_unix.go:172 +0x3e
2024-03-04T17:14:48.8867050Z net.(*TCPListener).accept(0xc001fce9c0)
2024-03-04T17:14:48.8867540Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/tcpsock_posix.go:152 +0x3e
2024-03-04T17:14:48.8867810Z net.(*TCPListener).Accept(0xc001fce9c0)
2024-03-04T17:14:48.8868260Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/tcpsock.go:315 +0x65
2024-03-04T17:14:48.8868580Z net/http.(*Server).Serve(0xc000dcc1e0, {0x27072b0, 0xc001fce9c0})
2024-03-04T17:14:48.8869070Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/server.go:3056 +0x5e8
2024-03-04T17:14:48.8869280Z net/http/httptest.(*Server).goServe.func1()
2024-03-04T17:14:48.8869820Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/httptest/server.go:310 +0xd0
2024-03-04T17:14:48.8870280Z created by net/http/httptest.(*Server).goServe in goroutine 592
2024-03-04T17:14:48.8870820Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/httptest/server.go:308 +0xa6
2024-03-04T17:14:48.8870830Z 
2024-03-04T17:14:48.8871010Z goroutine 133 [IO wait, 9 minutes]:
2024-03-04T17:14:48.8871230Z internal/poll.runtime_pollWait(0x4d400328, 0x72)
2024-03-04T17:14:48.8871710Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/runtime/netpoll.go:343 +0x85
2024-03-04T17:14:48.8872050Z internal/poll.(*pollDesc).wait(0xc0001a4420, 0xc000081a01?, 0x0)
2024-03-04T17:14:48.8872630Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_poll_runtime.go:84 +0xb1
2024-03-04T17:14:48.8872830Z internal/poll.(*pollDesc).waitRead(...)
2024-03-04T17:14:48.8873360Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_poll_runtime.go:89
2024-03-04T17:14:48.8873560Z internal/poll.(*FD).Accept(0xc0001a4400)
2024-03-04T17:14:48.8874180Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/internal/poll/fd_unix.go:611 +0x425
2024-03-04T17:14:48.8874350Z net.(*netFD).accept(0xc0001a4400)
2024-03-04T17:14:48.8874780Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/fd_unix.go:172 +0x3e
2024-03-04T17:14:48.8874960Z net.(*TCPListener).accept(0xc00018f480)
2024-03-04T17:14:48.8875450Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/tcpsock_posix.go:152 +0x3e
2024-03-04T17:14:48.8875630Z net.(*TCPListener).Accept(0xc00018f480)
2024-03-04T17:14:48.8876070Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/tcpsock.go:315 +0x65
2024-03-04T17:14:48.8876390Z net/http.(*Server).Serve(0xc0000ac0f0, {0x27072b0, 0xc00018f480})
2024-03-04T17:14:48.8876880Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/server.go:3056 +0x5e8
2024-03-04T17:14:48.8877090Z net/http/httptest.(*Server).goServe.func1()
2024-03-04T17:14:48.8877640Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/httptest/server.go:310 +0xd0
2024-03-04T17:14:48.8878000Z created by net/http/httptest.(*Server).goServe in goroutine 101
2024-03-04T17:14:48.8878540Z 	/Users/runner/hostedtoolcache/go/1.21.7/x64/src/net/http/httptest/server.go:308 +0xa6
2024-03-04T17:14:48.8878550Z 
2024-03-04T17:14:48.8878730Z goroutine 11213 [select, 8 minutes]:
2024-03-04T17:14:48.8879450Z github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).handleSubEvents(0xc004991180)
2024-03-04T17:14:48.8879980Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/server.go:2921 +0x86d
2024-03-04T17:14:48.8880670Z created by github.com/nspcc-dev/neo-go/pkg/services/rpcsrv.(*Server).Start in goroutine 11210
2024-03-04T17:14:48.8881180Z 	/Users/runner/work/neo-go/neo-go/pkg/services/rpcsrv/server.go:391 +0xf4
2024-03-04T17:14:48.8881190Z

AnnaShaleva
AnnaShaleva requested changes Mar 4, 2024
View reviewed changes
pkg/core/blockchain.go Outdated Show resolved Hide resolved
@AliceInHunterland AliceInHunterland changed the title blockchain: fix TestFailedPreconditionShutdown rpcsrv: fix TestFailedPreconditionShutdown shutdown Mar 5, 2024
AnnaShaleva
AnnaShaleva reviewed Mar 5, 2024
View reviewed changes
pkg/services/rpcsrv/server_helper_test.go Outdated Show resolved Hide resolved
pkg/services/rpcsrv/server_helper_test.go Outdated Show resolved Hide resolved
pkg/services/rpcsrv/server_helper_test.go Outdated Show resolved Hide resolved
AnnaShaleva
AnnaShaleva reviewed Mar 5, 2024
View reviewed changes
Copy link
Member

@AnnaShaleva AnnaShaleva left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Tests are failing, need to remove the following code from TestErrorResponseContentType:

	defer chain.Close()
	defer rpcSrv.Shutdown()

pkg/services/rpcsrv/server_helper_test.go Outdated Show resolved Hide resolved
@AliceInHunterland AliceInHunterland force-pushed the TestFailedPreconditionShutdown branch 3 times, most recently from 6a3038b to 123d41a Compare March 5, 2024 13:32
AnnaShaleva
AnnaShaleva reviewed Mar 5, 2024
View reviewed changes
pkg/services/rpcsrv/server_helper_test.go Outdated Show resolved Hide resolved
pkg/services/rpcsrv/server_helper_test.go Outdated Show resolved Hide resolved
pkg/services/rpcsrv/server_helper_test.go Outdated Show resolved Hide resolved
@AliceInHunterland
Copy link
Contributor Author

still problms with tcp traverse and traverseiterator on windows and mac

@AnnaShaleva
Copy link
Member

still problms with tcp traverse and traverseiterator on windows and mac

Don't reference those issues that are not solved and not related to this PR then. These two are separate problems.

AnnaShaleva
AnnaShaleva reviewed Mar 5, 2024
View reviewed changes
Copy link
Member

@AnnaShaleva AnnaShaleva left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Close #3312
Close #2956
Close #3005

Why?

pkg/rpcclient/wsclient_test.go Outdated Show resolved Hide resolved
pkg/rpcclient/wsclient_test.go Outdated Show resolved Hide resolved
pkg/rpcclient/wsclient_test.go Outdated Show resolved Hide resolved
@AliceInHunterland
rpcsrv: add close of blockchain and rpc server in tests
46f2da0 
The logs race issue is a result of improper shutdown during testing.

Close #3217

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
@AliceInHunterland
rpcsrv: add close of http server in tests
ee39b5c 
The HTTP server should be closed at the end of the test.

Signed-off-by: Ekaterina Pavlova <ekt@morphbits.io>
@AnnaShaleva
Copy link
Member

@roman-khimov, ready for review, you'll like this PR.

@roman-khimov roman-khimov merged commit 025bf22 into master Mar 6, 2024
15 of 18 checks passed
@roman-khimov roman-khimov deleted the TestFailedPreconditionShutdown branch March 6, 2024 07:24
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@roman-khimov roman-khimov roman-khimov approved these changes

@AnnaShaleva AnnaShaleva AnnaShaleva approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

Log in goroutine after TestFailedPreconditionShutdown has completed
3 participants
@AliceInHunterland @AnnaShaleva @roman-khimov