rpc: WebSocket client treats pings as errors

[dphilipson]

Hello!

If the Go-Ethereum client connects to a server via WebSockets and uses SubscribeNewHead, then if that server sends a WebSocket ping message, the client treats this as an error and closes the connection. According to the WebSocket spec, either the client or server may send ping messages and the other endpoint should respond with a pong (see MDN or the WebSocket spec). Instead, if the server sends a ping then the connection is closed with an error.

A repro is as follows, which creates a go-ethereum client that subscribes to a mock server. The mock server responds to the eth_subscribe request, then sends a WebSocket ping after 12 seconds.

package main

import (
	"context"
	"log"
	"sync"
	"time"

	"net/http"

	"github.com/ethereum/go-ethereum/core/types"
	"github.com/ethereum/go-ethereum/ethclient"
	"github.com/gorilla/websocket"
)

var waitGroup = &sync.WaitGroup{}
var upgrader = websocket.Upgrader{
	CheckOrigin: checkOrigin,
}

func main() {
	waitGroup.Add(2)
	go runServer()
	// Give server a moment to start up.
	time.Sleep(1 * time.Second)
	go runClient()
	waitGroup.Wait()
}

func runServer() {
	defer waitGroup.Done()
	http.HandleFunc("/", handleJSONRPCRequest)
	http.ListenAndServe("localhost:8080", nil)
}

func checkOrigin(r *http.Request) bool {
	return true
}

func handleJSONRPCRequest(writer http.ResponseWriter, request *http.Request) {
	conn, err := upgrader.Upgrade(writer, request, nil)
	if err != nil {
		log.Println(err)
		return
	}
	defer conn.Close()
	go func() {
		time.Sleep(12 * time.Second)
		log.Println("Server - Sending Ping")
		conn.WriteMessage(websocket.PingMessage, []byte("ping"))
	}()
	for {
		_, message, err := conn.ReadMessage()
		if err != nil {
			log.Println("Server - Read error:", err)
			break
		}
		log.Printf("Server - Received: %s", message)
		outMessage := []byte(`{"jsonrpc": "2.0", "id": 1, "result": "0x9ce59a13059e417087c02d3236a0b1cc"}`)
		err = conn.WriteMessage(websocket.TextMessage, outMessage)
		if err != nil {
			log.Println("Server - Write error:", err)
			break
		}
		log.Printf("Server - Sent: %s", outMessage)
	}
}

func runClient() {
	defer waitGroup.Done()
	endpoint := "ws://localhost:8080"
	ethWS, err := ethclient.Dial(endpoint)
	if err != nil {
		log.Fatal(err)
	}
	resultChan := make(chan *types.Header)
	subscription, err := ethWS.SubscribeNewHead(context.Background(), resultChan)
	if err != nil {
		log.Fatal(err)
	}
	log.Println("Client - Subscription successful, waiting for data ...")
	for {
		select {
		case sErr := <-subscription.Err():
			log.Println("Client - Saw error: ", sErr)
		case header := <-resultChan:
			log.Printf("Client - New block arrived, block_number: %v \n", header.Number)
		}
	}
}

Running this produces the output:

~/go/src/geth-repro$ ./geth-repro
2019/07/06 13:06:54 Server - Received: {"jsonrpc":"2.0","id":1,"method":"eth_subscribe","params":["newHeads"]}
2019/07/06 13:06:54 Server - Sent: {"jsonrpc": "2.0", "id": 1, "result": "0x9ce59a13059e417087c02d3236a0b1cc"}
2019/07/06 13:06:54 Client - Subscription successful, waiting for data ...
2019/07/06 13:07:06 Server - Sending Ping
2019/07/06 13:07:06 Client - Saw error:  write tcp 127.0.0.1:63875->127.0.0.1:8080: i/o timeout
2019/07/06 13:07:06 Server - Read error: websocket: close 1006 (abnormal closure): unexpected EOF

[dtran320]

+1 for adhering to the websocket spec—this caused us a lot of confusion while debugging

[halink0803]

I am also working with websocket and face this error also. It would be great if this error be fixed soon.

[fjl]

I will fix this by switching to github.com/gorilla/websocket.

[dphilipson]

More information: this bug is present in master (as of latest commit 7527215), but not in v1.8.27 (currently the latest released version).

Edit: The latest released version is now v1.9.0, and it does contain this bug.

[fjl]

OK, it took me a bit to understand the details but I have it now. The issue here isn't that github.com/x/net/websocket doesn't handle ping (it does). We are seeing the reproducer behave this way because SetWriteDeadline interacts badly with the built-in ping frame handler. Whenever the RPC client wants to write something, it sets a write deadline. In the reproducer it only writes once to establish the subscription. When the ping frame arrives 12 seconds after the write, the write deadline that's set has already passed and writing the pong frame fails. The pong write error is returned from Read, causing the client to reconnect.

[wenweih]

@dphilipson v1.9.0 can't work for SubscribeNewHead, need to update to latest (v1.9.1)