From 698bdc7eea807b5ebd2b33825c95cd6428929c2d Mon Sep 17 00:00:00 2001 From: Ekaterina Pavlova Date: Tue, 2 Apr 2024 15:13:13 +0300 Subject: [PATCH 1/2] rpcsrv: fix TestWSClientsLimit Made connections in parallel to check the limit and attempt to make one more connection beyond the limit. Only "default" test case is failing, because default number of connections is 64 (quite large for slow runners). The failure reason is: * given ~1 second for [dealing + request] per connection (time is taken from the test log) * by the moment 65-th connection is reached, some connections from the start of the test have died due to inactivity (this process literally takes 1 minute) Signed-off-by: Ekaterina Pavlova --- pkg/services/rpcsrv/subscription_test.go | 39 ++++++++++++++++-------- 1 file changed, 26 insertions(+), 13 deletions(-) diff --git a/pkg/services/rpcsrv/subscription_test.go b/pkg/services/rpcsrv/subscription_test.go index b37780688..41adcb61a 100644 --- a/pkg/services/rpcsrv/subscription_test.go +++ b/pkg/services/rpcsrv/subscription_test.go @@ -4,6 +4,7 @@ import ( "encoding/json" "fmt" "strings" + "sync" "testing" "time" @@ -604,25 +605,37 @@ func TestWSClientsLimit(t *testing.T) { dialer := websocket.Dialer{HandshakeTimeout: 5 * time.Second} url := "ws" + strings.TrimPrefix(httpSrv.URL, "http") + "/ws" wss := make([]*websocket.Conn, effectiveClients) + var wg sync.WaitGroup - for i := 0; i < len(wss)+1; i++ { - ws, r, err := dialer.Dial(url, nil) - if r != nil && r.Body != nil { - defer r.Body.Close() - } - if i < effectiveClients { + // Dial effectiveClients connections in parallel + for i := 0; i < effectiveClients; i++ { + wg.Add(1) + j := i + go func() { + defer wg.Done() + ws, r, err := dialer.Dial(url, nil) + if r != nil { + defer r.Body.Close() + } require.NoError(t, err) - wss[i] = ws - // Check that it's completely ready. + wss[j] = ws doSomeWSRequest(t, ws) - } else { - require.Error(t, err) - } + }() + } + + wg.Wait() + + // Attempt one more connection, which should fail + _, r, err := dialer.Dial(url, nil) + require.Error(t, err, "The connection beyond the limit should fail") + if r != nil { + r.Body.Close() } // Check connections are still alive (it actually is necessary to add // some use of wss to keep connections alive). - for i := 0; i < len(wss); i++ { - doSomeWSRequest(t, wss[i]) + for _, ws := range wss { + doSomeWSRequest(t, ws) + ws.Close() } }) } From f8c2d269fe00afe7c50543969727e60bb906fa13 Mon Sep 17 00:00:00 2001 From: Ekaterina Pavlova Date: Wed, 3 Apr 2024 17:41:40 +0300 Subject: [PATCH 2/2] rpcsrv: increase timeout in TestWSClientsLimit MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Still not fast enough for connections to be alive for the default case of 64+1 connections. Some of them are start to die after 5 seconds of test: ``` 2024-04-03T14:06:22.5504034Z === RUN TestWSClientsLimit 2024-04-03T14:06:22.5504142Z === RUN TestWSClientsLimit/default 2024-04-03T14:06:22.5504868Z logger.go:146: 2024-04-03T14:04:30.637Z INFO initial gas supply is not set or wrong, setting default value {"InitialGASSupply": "52000000"} 2024-04-03T14:06:22.5505730Z logger.go:146: 2024-04-03T14:04:30 .637Z INFO P2PNotaryRequestPayloadPool size is not set or wrong, setting default value {"P2PNotaryRequestPayloadPoolSize": 1000} 2024-04-03T14:06:22.5506373Z logger.go:146: 2024-04-03T14:04:30 .637Z INFO MaxBlockSize is not set or wrong, setting default value {"MaxBlockSize": 262144} 2024-04-03T14:06:22.5507094Z logger.go:146: 2024-04-03T14:04:30 .637Z INFO MaxBlockSystemFee is not set or wrong, setting default value {"MaxBlockSystemFee": 900000000000} 2024-04-03T14:06:22.5507843Z logger.go:146: 2024-04-03T14:04:30 .637Z INFO MaxTransactionsPerBlock is not set or wrong, using default value {"MaxTransactionsPerBlock": 512} 2024-04-03T14:06:22.5508644Z logger.go:146: 2024-04-03T14:04:30 .637Z INFO MaxValidUntilBlockIncrement is not set or wrong, using default value {"MaxValidUntilBlockIncrement": 5760} 2024-04-03T14:06:22.5509114Z logger.go:146: 2024-04-03T14:04:30 .637Z INFO no storage version found! creating genesis block 2024-04-03T14:06:22.5509788Z logger.go:146: 2024-04-03T14:04:30 .637Z INFO ExtensiblePoolSize is not set or wrong, using default value {"ExtensiblePoolSize": 20} 2024-04-03T14:06:22.5510476Z logger.go:146: 2024-04-03T14:04:30 .637Z INFO SessionPoolSize is not set or wrong, setting default value {"SessionPoolSize": 20} 2024-04-03T14:06:22.5511258Z logger.go:146: 2024-04-03T14:04:30 .637Z INFO MaxIteratorResultItems is not set or wrong, setting default value {"MaxIteratorResultItems": 100} 2024-04-03T14:06:22.5511951Z logger.go:146: 2024-04-03T14:04:30 .637Z INFO MaxFindResultItems is not set or wrong, setting default value {"MaxFindResultItems": 100} 2024-04-03T14:06:22.5512598Z logger.go:146: 2024-04-03T14:04:30 .637Z INFO MaxNEP11Tokens is not set or wrong, setting default value {"MaxNEP11Tokens": 100} 2024-04-03T14:06:22.5513316Z logger.go:146: 2024-04-03T14:04:30 .637Z INFO MaxRequestBodyBytes is not set or wong, setting default value {"MaxRequestBodyBytes": 5242880} 2024-04-03T14:06:22.5514060Z logger.go:146: 2024-04-03T14:04:30 .637Z INFO MaxRequestHeaderBytes is not set or wong, setting default value {"MaxRequestHeaderBytes": 1048576} 2024-04-03T14:06:22.5514755Z logger.go:146: 2024-04-03T14:04:30 .637Z INFO MaxWebSocketClients is not set or wrong, setting default value {"MaxWebSocketClients": 64} 2024-04-03T14:06:22.5515215Z logger.go:146: 2024-04-03T14:04:30 .637Z INFO starting rpc-server {"endpoint": "127.0.0.1:0"} 2024-04-03T14:06:22.5515874Z logger.go:146: 2024-04-03T14:04:31 .200Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5516442Z logger.go:146: 2024-04-03T14:04:31 .200Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5516973Z logger.go:146: 2024-04-03T14:04:31 .226Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5517502Z logger.go:146: 2024-04-03T14:04:31 .388Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5518027Z logger.go:146: 2024-04-03T14:04:31 .398Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5518551Z logger.go:146: 2024-04-03T14:04:31 .420Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5519082Z logger.go:146: 2024-04-03T14:04:31 .577Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5519606Z logger.go:146: 2024-04-03T14:04:31 .587Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5520133Z logger.go:146: 2024-04-03T14:04:31 .624Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5520850Z logger.go:146: 2024-04-03T14:04:31 .780Z INFO persisted to disk {"blocks": 0, "keys": 127, "headerHeight": 0, "blockHeight": 0, "took": "121.8µs"} 2024-04-03T14:06:22.5521398Z logger.go:146: 2024-04-03T14:04:31 .780Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5521925Z logger.go:146: 2024-04-03T14:04:31 .812Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5522452Z logger.go:146: 2024-04-03T14:04:31 .969Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5522975Z logger.go:146: 2024-04-03T14:04:32 .016Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5523507Z logger.go:146: 2024-04-03T14:04:32 .172Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5524033Z logger.go:146: 2024-04-03T14:04:32 .219Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5524555Z logger.go:146: 2024-04-03T14:04:32 .273Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5525081Z logger.go:146: 2024-04-03T14:04:32 .376Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5525604Z logger.go:146: 2024-04-03T14:04:32 .423Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5526131Z logger.go:146: 2024-04-03T14:04:32 .563Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5526691Z logger.go:146: 2024-04-03T14:04:32 .627Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5527254Z logger.go:146: 2024-04-03T14:04:32 .767Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5527777Z logger.go:146: 2024-04-03T14:04:32 .830Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5528304Z logger.go:146: 2024-04-03T14:04:32 .955Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5528824Z logger.go:146: 2024-04-03T14:04:33 .033Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5529352Z logger.go:146: 2024-04-03T14:04:33 .158Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5529871Z logger.go:146: 2024-04-03T14:04:33 .237Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5530395Z logger.go:146: 2024-04-03T14:04:33 .322Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5530921Z logger.go:146: 2024-04-03T14:04:33 .348Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5531472Z logger.go:146: 2024-04-03T14:04:33 .444Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5532031Z logger.go:146: 2024-04-03T14:04:33 .535Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5532555Z logger.go:146: 2024-04-03T14:04:33 .645Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5533084Z logger.go:146: 2024-04-03T14:04:33 .724Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5533604Z logger.go:146: 2024-04-03T14:04:33 .848Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5534132Z logger.go:146: 2024-04-03T14:04:33 .926Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5534662Z logger.go:146: 2024-04-03T14:04:34 .036Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5535190Z logger.go:146: 2024-04-03T14:04:34 .130Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5535712Z logger.go:146: 2024-04-03T14:04:34 .224Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5536231Z logger.go:146: 2024-04-03T14:04:34 .318Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5536758Z logger.go:146: 2024-04-03T14:04:34 .413Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5537277Z logger.go:146: 2024-04-03T14:04:34 .423Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5537805Z logger.go:146: 2024-04-03T14:04:34 .423Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5538329Z logger.go:146: 2024-04-03T14:04:34 .523Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5538855Z logger.go:146: 2024-04-03T14:04:34 .602Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5539382Z logger.go:146: 2024-04-03T14:04:34 .612Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5539908Z logger.go:146: 2024-04-03T14:04:34 .712Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5540431Z logger.go:146: 2024-04-03T14:04:34 .805Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5540956Z logger.go:146: 2024-04-03T14:04:34 .915Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5541515Z logger.go:146: 2024-04-03T14:04:34 .993Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5542070Z logger.go:146: 2024-04-03T14:04:35 .118Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5542599Z logger.go:146: 2024-04-03T14:04:35 .181Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5543125Z logger.go:146: 2024-04-03T14:04:35 .307Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5543650Z logger.go:146: 2024-04-03T14:04:35 .385Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5544169Z logger.go:146: 2024-04-03T14:04:35 .426Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5544695Z logger.go:146: 2024-04-03T14:04:35 .510Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5545262Z logger.go:146: 2024-04-03T14:04:35 .589Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5545839Z logger.go:146: 2024-04-03T14:04:35 .698Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5546421Z logger.go:146: 2024-04-03T14:04:35 .777Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5547045Z logger.go:146: 2024-04-03T14:04:35 .902Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5547593Z logger.go:146: 2024-04-03T14:04:35 .980Z DEBUG processing rpc request {"method": "getversion", "params": "[]"} 2024-04-03T14:06:22.5551421Z subscription_test.go:620: 2024-04-03T14:06:22.5551977Z Error Trace: D:/a/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:620 2024-04-03T14:06:22.5552611Z C:/hostedtoolcache/windows/go/1.22.1/x64/src/runtime/asm_amd64.s:1695 2024-04-03T14:06:22.5552821Z Error: Received unexpected error: 2024-04-03T14:06:22.5553328Z read tcp 127.0 .0.1:51969->127.0.0.1:51909: i/o timeout 2024-04-03T14:06:22.5553535Z Test: TestWSClientsLimit/default 2024-04-03T14:06:22.5553676Z subscription_test.go:620: 2024-04-03T14:06:22.5554223Z Error Trace: D:/a/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:620 2024-04-03T14:06:22.5554831Z C:/hostedtoolcache/windows/go/1.22.1/x64/src/runtime/asm_amd64.s:1695 2024-04-03T14:06:22.5555036Z Error: Received unexpected error: 2024-04-03T14:06:22.5555521Z read tcp 127.0 .0.1:51970->127.0.0.1:51909: i/o timeout 2024-04-03T14:06:22.5555723Z Test: TestWSClientsLimit/default 2024-04-03T14:06:22.5555860Z subscription_test.go:620: 2024-04-03T14:06:22.5556336Z Error Trace: D:/a/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:620 2024-04-03T14:06:22.5556953Z C:/hostedtoolcache/windows/go/1.22.1/x64/src/runtime/asm_amd64.s:1695 2024-04-03T14:06:22.5557160Z Error: Received unexpected error: 2024-04-03T14:06:22.5557636Z read tcp 127.0 .0.1:51973->127.0.0.1:51909: i/o timeout 2024-04-03T14:06:22.5557831Z Test: TestWSClientsLimit/default 2024-04-03T14:06:22.5557967Z subscription_test.go:620: 2024-04-03T14:06:22.5558437Z Error Trace: D:/a/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:620 2024-04-03T14:06:22.5559028Z C:/hostedtoolcache/windows/go/1.22.1/x64/src/runtime/asm_amd64.s:1695 2024-04-03T14:06:22.5559229Z Error: Received unexpected error: 2024-04-03T14:06:22.5559696Z read tcp 127.0 .0.1:51971->127.0.0.1:51909: i/o timeout 2024-04-03T14:06:22.5559891Z Test: TestWSClientsLimit/default 2024-04-03T14:06:22.5560024Z subscription_test.go:620: 2024-04-03T14:06:22.5560490Z Error Trace: D:/a/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:620 2024-04-03T14:06:22.5561142Z C:/hostedtoolcache/windows/go/1.22.1/x64/src/runtime/asm_amd64.s:1695 2024-04-03T14:06:22.5561371Z Error: Received unexpected error: 2024-04-03T14:06:22.5561849Z read tcp 127.0 .0.1:51972->127.0.0.1:51909: i/o timeout 2024-04-03T14:06:22.5562043Z Test: TestWSClientsLimit/default 2024-04-03T14:06:22.5562179Z subscription_test.go:630: 2024-04-03T14:06:22.5562638Z Error Trace: D:/a/neo-go/neo-go/pkg/services/rpcsrv/subscription_test.go:630 2024-04-03T14:06:22.5562879Z Error: An error is expected but got nil. 2024-04-03T14:06:22.5563073Z Test: TestWSClientsLimit/default 2024-04-03T14:06:22.5563361Z Messages: The connection beyond the limit should fail 2024-04-03T14:06:22.5563886Z logger.go:146: 2024-04-03T14:04:36 .481Z INFO shutting down RPC server {"endpoint": "127.0.0 .1:51908"} ``` Close #3379 Signed-off-by: Ekaterina Pavlova --- pkg/services/rpcsrv/subscription_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pkg/services/rpcsrv/subscription_test.go b/pkg/services/rpcsrv/subscription_test.go index 41adcb61a..b45c990b0 100644 --- a/pkg/services/rpcsrv/subscription_test.go +++ b/pkg/services/rpcsrv/subscription_test.go @@ -602,7 +602,7 @@ func TestWSClientsLimit(t *testing.T) { cfg.ApplicationConfiguration.RPC.MaxWebSocketClients = limit }) - dialer := websocket.Dialer{HandshakeTimeout: 5 * time.Second} + dialer := websocket.Dialer{HandshakeTimeout: 10 * time.Second} url := "ws" + strings.TrimPrefix(httpSrv.URL, "http") + "/ws" wss := make([]*websocket.Conn, effectiveClients) var wg sync.WaitGroup