RPC vote event problems

[liuyangc3]

Tendermint version (use tendermint version or git rev-parse --verify HEAD if installed from source):

$ lino tendermint version
tendermint: 0.32.6
abci: 0.16.1
blockprotocol: 10
p2pprotocol: 7

ABCI app (name for built-in, URL for self-written if it's publicly available):
Lino testnet
Environment:

• OS (e.g. from /etc/os-release): Ubuntu 1804
• Install tools:
• Others:

What happened:
event stoped

$ go run main.go
height=508062 type=1 round=0
height=508063 type=1 round=0
height=508064 type=1 round=0
height=508065 type=1 round=0
height=508066 type=1 round=0
height=508067 type=1 round=0
height=508068 type=1 round=0
height=508069 type=1 round=0
height=508070 type=1 round=0
height=508071 type=1 round=0
height=508072 type=1 round=0
height=508073 type=1 round=0
height=508074 type=1 round=0
height=508075 type=1 round=0
height=508076 type=1 round=0
height=508077 type=1 round=0
height=508078 type=1 round=0
height=508079 type=1 round=0
height=508080 type=1 round=0
height=508081 type=1 round=0
height=508082 type=1 round=0
height=508083 type=1 round=0
height=508084 type=1 round=0
height=508085 type=1 round=0
height=508086 type=1 round=0
height=508087 type=1 round=0
height=508088 type=1 round=0
height=508089 type=1 round=0
height=508090 type=1 round=0
height=508091 type=1 round=0
height=508092 type=1 round=0
height=508093 type=1 round=0

# no more output

What you expected to happen:
event should not stop print

Have you tried the latest version: yes/no
no
How to reproduce it (as minimally and precisely as possible):

package main

import (
	"context"
	"fmt"

	"github.com/tendermint/tendermint/rpc/client"
	"github.com/tendermint/tendermint/types"
)

func main()  {
	c := client.NewHTTP("tcp://localhost:26657", "/websocket")
	err := c.Start()
	if err != nil {
		panic(err)
	}
	defer c.Stop()

	// Subscribe Vote events
	ctx, cancel := context.WithCancel(context.Background())
	events, err := c.Subscribe(ctx, "tendermint-ws-client", "tm.event = 'Vote'")
	if err != nil {
		panic(err)
	}
	defer cancel()

	// Check events
	var lastHeight int64 = 0
	for e := range events {
		vote := e.Data.(types.EventDataVote).Vote

		if lastHeight == 0 {
			lastHeight = vote.Height
		}

		if vote.Height > lastHeight {
			// new Block Height
			fmt.Printf("height=%d type=%d round=%d\n", vote.Height, vote.Type, vote.Round)
			lastHeight = vote.Height
		}
	}
}

then run export GO111MODULE=on go run main.go
Logs (paste a small part showing an error (< 10 lines) or link a pastebin, gist, etc. containing more of the log file):

Config (you can paste only the changes you've made):
no change
node command runtime flags:

/dump_consensus_state output for consensus bugs

Anything else we need to know:
I got this when doing HTTP traffic capture by sudo tcpdump -A -i lo -s 0 'tcp port 26657 and (((ip[2:2] - ((ip[0]&0xf)<<2)) - ((tcp[12]&0xf0)>>2)) != 0)'

04:11:44.340891 IP localhost.26657 > localhost.36834: Flags [P.], seq 1053416:1053632, ack 25, win 350, length 216
E...H.@.@...........h!..C.kt..=.P..^.....~..{
  "jsonrpc": "2.0",
  "id": "ws-client#event",
  "error": {
    "code": -32000,
    "message": "Server error",
    "data": "subscription was cancelled (reason: client is not pulling messages fast enough)"
  }
}
04:11:45.341917 IP localhost.36834 > localhost.26657: Flags [P.], seq 25:126, ack 1053632, win 8692, length 101
E...,.@.@.............h!..=.C.lLP.!...........w...c...o...>... ...........e.......i...h.......o...i...|...a...w...i...6..."...b...,...x...q..
04:11:45.342520 IP localhost.26657 > localhost.36834: Flags [P.], seq 1053632:1053783, ack 126, win 350, length 151
E...H.@.@..<........h!..C.lL..=.P..^.....~..{
  "jsonrpc": "2.0",
  "id": "ws-client",
  "error": {
    "code": -32603,
    "message": "Internal error",
    "data": "already subscribed"
  }
}

[liuyangc3]

I tried Subscribe with 1000 outCapacity, still got same error.
I saw there is a method SubscribeUnbuffered in pubsub code, but this method is not exposed to wsclient .

And I think the reason is not the client pulling messages not fast enough(code above basically do nothing just print event), and it should be the websocket performance.

[PashaKlybik]

I also ran into this problem where in block has more 2 txs. And transaction is being processed on client about time=7.477µs

[ebuchman]

Is this fixed by #4279 ?

[melekes]

Related #3935

[melekes]

Duplicate of #3935