rpc: fix client websocket timeout

[alexppxela]

Since version 0.10.2, ping/pong between server and client are broken. Server is not notified that client is alive because pong message was not handled.
Each 30 seconds, log "Failed to read request" appeared.

[codecov-io]

Codecov Report

Merging #687 into master will decrease coverage by 0.34%.
The diff coverage is 0%.

@@            Coverage Diff             @@
##           master     #687      +/-   ##
==========================================
- Coverage   56.63%   56.29%   -0.35%     
==========================================
  Files          81       81              
  Lines        8401     8404       +3     
==========================================
- Hits         4758     4731      -27     
- Misses       3240     3267      +27     
- Partials      403      406       +3

[melekes]

Somehow missed that while I was developing it. Thanks for spotting and fixing it!

[odeke-em]

@melekes later on, is there a way we could add a test to ensure that we don't regress in the future?

[melekes]

There is a test https://github.com/tendermint/tendermint/blob/develop/rpc/lib/rpc_test.go#L358 for this

[odeke-em]

Hmm, is the test new, or do we need perhaps to update it then, since we didn't catch this issue?

[melekes]

Oh, I see. We need to increase the sleep time to be greater than readTimeout.

[odeke-em]

So currently even before applying this patch i.e working directly on develop 7682ad9 before your patch @melekes(timeout increment) or yours either @alexppxela(this current patch),
given this diff

diff --git a/rpc/lib/rpc_test.go b/rpc/lib/rpc_test.go
index 3ceaaa3..9b90f64 100644
--- a/rpc/lib/rpc_test.go
+++ b/rpc/lib/rpc_test.go
@@ -356,13 +356,18 @@ func TestWSHandlesArrayParams(t *testing.T) {
 // TestWSClientPingPong checks that a client & server exchange pings
 // & pongs so connection stays alive.
 func TestWSClientPingPong(t *testing.T) {
-	cl := client.NewWSClient(tcpAddr, websocketEndpoint)
-	cl.SetLogger(log.TestingLogger())
+	buf := new(bytes.Buffer)
+	cl := client.NewWSClient(tcpAddr, websocketEndpoint, client.PingPeriod(70*time.Millisecond))
+	logger := log.NewTMLogger(buf)
+	cl.SetLogger(logger)
 	_, err := cl.Start()
 	require.Nil(t, err)
-	defer cl.Stop()
+	time.Sleep(3 * time.Second)
+	cl.Stop()
 
-	time.Sleep(6 * time.Second)
+	outLog := buf.Bytes()
+	require.True(t, bytes.Contains(outLog, []byte("sent ping")), "expecting pings to have been sent")
+	require.True(t, bytes.Contains(outLog, []byte("got pong")), "expecting pongs to have been received")
 }
 
 func randBytes(t *testing.T) []byte {

After running test, we get back

$ go test -v -run=PingPong
I[09-29|08:44:16.549] Starting RPC HTTP server on unix socket /tmp/rpc_test.sock socket=unix
I[09-29|08:44:16.549] Starting RPC HTTP server on tcp socket 0.0.0.0:47768 socket=tcp
=== RUN   TestWSClientPingPong
I[09-29|08:44:18.551] New websocket connection                     socket=tcp remote=127.0.0.1:52153
I[09-29|08:44:18.551] Starting wsConnection                        socket=tcp remote=127.0.0.1:52153 impl=wsConnection
--- PASS: TestWSClientPingPong (3.00s)
I[09-29|08:44:21.554] Client closed the connection                 socket=tcp remote=127.0.0.1:52153
I[09-29|08:44:21.554] Stopping wsConnection                        socket=tcp remote=127.0.0.1:52153 impl=wsConnection
PASS
ok  	github.com/tendermint/tendermint/rpc/lib	5.028s

Am I missing something?

[melekes]

@odeke-em both client and server can send ping/pongs. server sends pings to check up on the client. there is no need for a client to send pings usually (unless it wants to measure latency or something).

The problem was that we forgot to reset the read deadline upon receiving a pong from a client.