[NOD-122] Fix timeout for get block template requests (#254)

* [NOD-122] Handle each message in rpcclient with a separate goroutine

* [NOD-122] Stop listening to new blocks when not mining

* [NOD-122] Made RPC logging in mining simulator more explicit + some styling enhencement

mining/simulator/client.go

@@ -0,0 +1,39 @@
+package main
+
+import (
+	"fmt"
+
+	"github.com/daglabs/btcd/rpcclient"
+	"github.com/daglabs/btcd/util"
+	"github.com/daglabs/btcd/wire"
+)
+
+type simulatorClient struct {
+	*rpcclient.Client
+	onBlockAdded       chan struct{}
+	notifyForNewBlocks bool
+}
+
+func newSimulatorClient(address string, connCfg *rpcclient.ConnConfig) (*simulatorClient, error) {
+	client := &simulatorClient{
+		onBlockAdded: make(chan struct{}, 1),
+	}
+	notificationHandlers := &rpcclient.NotificationHandlers{
+		OnFilteredBlockAdded: func(height int32, header *wire.BlockHeader,
+			txs []*util.Tx) {
+			if client.notifyForNewBlocks {
+				client.onBlockAdded <- struct{}{}
+			}
+		},
+	}
+	var err error
+	client.Client, err = rpcclient.New(connCfg, notificationHandlers)
+	if err != nil {
+		return nil, fmt.Errorf("Error connecting to address %s: %s", address, err)
+	}
+
+	if err = client.NotifyBlocks(); err != nil {
+		return nil, fmt.Errorf("Error while registering client %s for block notifications: %s", client.Host(), err)
+	}
+	return client, nil
+}

mining/simulator/config.go

@@ -10,6 +10,7 @@ type config struct {
 	AddressListPath string `long:"addresslist" description:"Path to a list of nodes' JSON-RPC endpoints" required:"true"`
 	CertificatePath string `long:"cert" description:"Path to certificate accepted by JSON-RPC endpoint"`
 	DisableTLS      bool   `long:"notls" description:"Disable TLS"`
+	Verbose         bool   `long:"verbose" short:"v" description:"Enable logging of RPC requests"`
 }
 
 func parseConfig() (*config, error) {

mining/simulator/connect.go

@@ -6,15 +6,9 @@ import (
 	"log"
 	"time"
 
-	"github.com/daglabs/btcd/dagconfig/daghash"
 	"github.com/daglabs/btcd/rpcclient"
 )
 
-type simulatorClient struct {
-	*rpcclient.Client
-	onBlockAdded chan struct{}
-}
-
 func connectToServers(cfg *config, addressList []string) ([]*simulatorClient, error) {
 	clients := make([]*simulatorClient, len(addressList))
 
@@ -28,12 +22,6 @@ func connectToServers(cfg *config, addressList []string) ([]*simulatorClient, er
 	}
 
 	for i, address := range addressList {
-		onBlockAdded := make(chan struct{}, 1)
-		ntfnHandlers := &rpcclient.NotificationHandlers{
-			OnBlockAdded: func(hash *daghash.Hash, height int32, t time.Time) {
-				onBlockAdded <- struct{}{}
-			},
-		}
 		connCfg := &rpcclient.ConnConfig{
 			Host:           address,
 			Endpoint:       "ws",
@@ -47,18 +35,10 @@ func connectToServers(cfg *config, addressList []string) ([]*simulatorClient, er
 			connCfg.Certificates = cert
 		}
 
-		client, err := rpcclient.New(connCfg, ntfnHandlers)
+		var err error
+		clients[i], err = newSimulatorClient(address, connCfg)
 		if err != nil {
-			return nil, fmt.Errorf("Error connecting to address %s: %s", address, err)
-		}
-
-		if err := client.NotifyBlocks(); err != nil {
-			return nil, fmt.Errorf("Error while registering client %s for block notifications: %s", client.Host(), err)
-		}
-
-		clients[i] = &simulatorClient{
-			Client:       client,
-			onBlockAdded: onBlockAdded,
+			return nil, err
 		}
 
 		log.Printf("Connected to server %s", address)

mining/simulator/log.go

@@ -0,0 +1,24 @@
+package main
+
+import (
+	"log"
+
+	"github.com/btcsuite/btclog"
+	"github.com/daglabs/btcd/rpcclient"
+)
+
+type logWriter struct{}
+
+func (logWriter) Write(p []byte) (n int, err error) {
+	log.Print(string(p))
+	return len(p), nil
+}
+
+func enableRPCLogging() {
+	backendLog := btclog.NewBackend(logWriter{})
+	rpclog := backendLog.Logger("RPCC")
+	rpclog.SetLevel(btclog.LevelTrace)
+	rpcclient.UseLogger(rpclog)
+
+	log.SetFlags(log.LstdFlags | log.Lmicroseconds)
+}

mining/simulator/main.go

@@ -2,21 +2,25 @@ package main
 
 import (
 	"fmt"
-	"github.com/daglabs/btcd/signal"
 	"log"
 	"os"
 	"runtime/debug"
+
+	"github.com/daglabs/btcd/signal"
 )
 
 func main() {
 	defer handlePanic()
-
 	cfg, err := parseConfig()
 	if err != nil {
 		fmt.Fprintf(os.Stderr, "Error parsing command-line arguments: %s", err)
 		os.Exit(1)
 	}
 
+	if cfg.Verbose {
+		enableRPCLogging()
+	}
+
 	addressList, err := getAddressList(cfg)
 	if err != nil {
 		panic(fmt.Errorf("Couldn't load address list: %s", err))

mining/simulator/mineloop.go

@@ -79,6 +79,11 @@ func getBlockTemplate(client *simulatorClient, longPollID string) (*btcjson.GetB
 func templatesLoop(client *simulatorClient, newTemplateChan chan *btcjson.GetBlockTemplateResult, errChan chan error, stopChan chan struct{}) {
 	longPollID := ""
 	getBlockTemplateLongPoll := func() {
+		if longPollID != "" {
+			log.Printf("Requesting template with longPollID '%s' from %s", longPollID, client.Host())
+		} else {
+			log.Printf("Requesting template without longPollID from %s", client.Host())
+		}
 		template, err := getBlockTemplate(client, longPollID)
 		if err == rpcclient.ErrResponseTimedOut {
 			log.Printf("Got timeout while requesting template '%s' from %s", longPollID, client.Host())
@@ -163,6 +168,7 @@ func mineLoop(clients []*simulatorClient) error {
 	go func() {
 		for {
 			currentClient := getRandomClient(clients)
+			currentClient.notifyForNewBlocks = true
 			log.Printf("Next block will be mined by: %s", currentClient.Host())
 			mineNextBlock(currentClient, foundBlock, templateStopChan, errChan)
 			block, ok := <-foundBlock
@@ -170,6 +176,7 @@ func mineLoop(clients []*simulatorClient) error {
 				errChan <- nil
 				return
 			}
+			currentClient.notifyForNewBlocks = false
 			err := handleFoundBlock(currentClient, block, templateStopChan)
 			if err != nil {
 				errChan <- err

rpcclient/infrastructure.go

@@ -431,7 +431,7 @@ out:
 			}
 			break out
 		}
-		c.handleMessage(msg)
+		go c.handleMessage(msg)
 	}
 
 	// Ensure the connection is closed.