woop/consensus/consensus_leader.go

package consensus

import (
	"encoding/hex"
	"strconv"
	"time"

	"github.com/ethereum/go-ethereum/rlp"
	protobuf "github.com/golang/protobuf/proto"
	"github.com/harmony-one/bls/ffi/go/bls"
	msg_pb "github.com/harmony-one/harmony/api/proto/message"
	"github.com/harmony-one/harmony/api/service/explorer"
	"github.com/harmony-one/harmony/core"
	"github.com/harmony-one/harmony/core/types"
	bls_cosi "github.com/harmony-one/harmony/crypto/bls"
	"github.com/harmony-one/harmony/internal/profiler"
	"github.com/harmony-one/harmony/internal/utils"
	"github.com/harmony-one/harmony/p2p"
	"github.com/harmony-one/harmony/p2p/host"
)

const (
	waitForEnoughValidators = 1000
)

var (
	startTime time.Time
)

// WaitForNewBlock waits for the next new block to run consensus on
func (consensus *Consensus) WaitForNewBlock(blockChannel chan *types.Block, stopChan chan struct{}, stoppedChan chan struct{}, startChannel chan struct{}) {
	// gensis block is the first block to be processed.
	// But we shouldn't start consensus yet, as we need to wait for all validators
	// received the leader's pub key which will be propogated via Pong message.
	// After we started the first consensus, we will go back to normal case to wait
	// for new blocks.
	// The signal to start the first consensus right now is the sending of Pong message (SendPongMessage function in node/node_handler.go
	// but it can be changed to other conditions later
	first := true
	go func() {
		defer close(stoppedChan)
		for {
			select {
			default:
				if first && startChannel != nil {
					// got the signal to start consensus
					_ = <-startChannel
					first = false
				}

				utils.GetLogInstance().Debug("Waiting for block", "consensus", consensus)
				// keep waiting for new blocks
				newBlock := <-blockChannel
				// TODO: think about potential race condition

				c := consensus.RemovePeers(consensus.OfflinePeerList)
				if c > 0 {
					utils.GetLogInstance().Debug("WaitForNewBlock", "removed peers", c)
				}

				if core.IsEpochBlock(newBlock) {
					// Receive pRnd from DRG protocol
					utils.GetLogInstance().Debug("[DRG] Waiting for pRnd")
					pRndAndBitmap := <-consensus.PRndChannel
					utils.GetLogInstance().Debug("[DRG] GOT pRnd", "pRnd", pRndAndBitmap)
					pRnd := [32]byte{}
					copy(pRnd[:], pRndAndBitmap[:32])
					bitmap := pRndAndBitmap[32:]
					vrfBitmap, _ := bls_cosi.NewMask(consensus.PublicKeys, consensus.leader.PubKey)
					vrfBitmap.SetMask(bitmap)

					// TODO: check validity of pRnd
					newBlock.AddRandPreimage(pRnd)
				}
				rnd, blockHash, err := consensus.GetNextRnd()
				if err == nil {
					// Verify the randomness
					_ = blockHash
					utils.GetLogInstance().Info("Adding randomness into new block", "rnd", rnd)
					newBlock.AddRandSeed(rnd)
				} else {
					utils.GetLogInstance().Info("Failed to get randomness", "error", err)
				}
				startTime = time.Now()
				utils.GetLogInstance().Debug("STARTING CONSENSUS", "numTxs", len(newBlock.Transactions()), "consensus", consensus, "startTime", startTime, "publicKeys", len(consensus.PublicKeys))
				for { // Wait until last consensus is finished
					if consensus.state == Finished {
						consensus.ResetState()
						consensus.startConsensus(newBlock)
						break
					}
					time.Sleep(500 * time.Millisecond)
				}
			case <-stopChan:
				return
			}
		}
	}()
}

// ProcessMessageLeader dispatches consensus message for the leader.
func (consensus *Consensus) ProcessMessageLeader(payload []byte) {
	message := &msg_pb.Message{}
	err := protobuf.Unmarshal(payload, message)

	if err != nil {
		utils.GetLogInstance().Error("Failed to unmarshal message payload.", "err", err, "consensus", consensus)
	}

	switch message.Type {
	case msg_pb.MessageType_PREPARE:
		consensus.processPrepareMessage(message)
	case msg_pb.MessageType_COMMIT:
		consensus.processCommitMessage(message)
	default:
		utils.GetLogInstance().Error("Unexpected message type", "msgType", message.Type, "consensus", consensus)
	}
}

// startConsensus starts a new consensus for a block by broadcast a announce message to the validators
func (consensus *Consensus) startConsensus(newBlock *types.Block) {
	// Copy over block hash and block header data
	blockHash := newBlock.Hash()
	copy(consensus.blockHash[:], blockHash[:])

	utils.GetLogInstance().Debug("Start encoding block")
	// prepare message and broadcast to validators
	encodedBlock, err := rlp.EncodeToBytes(newBlock)
	if err != nil {
		utils.GetLogInstance().Debug("Failed encoding block")
		return
	}
	consensus.block = encodedBlock
	utils.GetLogInstance().Debug("Stop encoding block")

	msgToSend := consensus.constructAnnounceMessage()

	// Set state to AnnounceDone
	consensus.state = AnnounceDone

	// Leader sign the block hash itself
	consensus.prepareSigs[consensus.nodeID] = consensus.priKey.SignHash(consensus.blockHash[:])

	// Construct broadcast p2p message
	utils.GetLogInstance().Warn("[Consensus]", "sent announce message", len(msgToSend))
	consensus.host.SendMessageToGroups([]p2p.GroupID{p2p.GroupIDBeacon}, host.ConstructP2pMessage(byte(17), msgToSend))
}

// processPrepareMessage processes the prepare message sent from validators
func (consensus *Consensus) processPrepareMessage(message *msg_pb.Message) {
	consensusMsg := message.GetConsensus()

	validatorID := consensusMsg.SenderId
	prepareSig := consensusMsg.Payload

	prepareSigs := consensus.prepareSigs
	prepareBitmap := consensus.prepareBitmap

	consensus.mutex.Lock()
	defer consensus.mutex.Unlock()

	validatorPeer := consensus.getValidatorPeerByID(validatorID)

	if validatorPeer == nil {
		utils.GetLogInstance().Error("Invalid validator", "validatorID", validatorID)
		return
	}

	if err := consensus.checkConsensusMessage(message, validatorPeer.PubKey); err != nil {
		utils.GetLogInstance().Debug("Failed to check the validator message", "validatorID", validatorID)
		return
	}

	// proceed only when the message is not received before
	_, ok := prepareSigs[validatorID]
	if ok {
		utils.GetLogInstance().Debug("Already received prepare message from the validator", "validatorID", validatorID)
		return
	}

	if len(prepareSigs) >= ((len(consensus.PublicKeys)*2)/3 + 1) {
		utils.GetLogInstance().Debug("Received additional prepare message", "validatorID", validatorID)
		return
	}

	// Check BLS signature for the multi-sig
	var sign bls.Sign
	err := sign.Deserialize(prepareSig)
	if err != nil {
		utils.GetLogInstance().Error("Failed to deserialize bls signature", "validatorID", validatorID)
		return
	}

	if !sign.VerifyHash(validatorPeer.PubKey, consensus.blockHash[:]) {
		utils.GetLogInstance().Error("Received invalid BLS signature", "validatorID", validatorID)
		return
	}

	utils.GetLogInstance().Debug("Received new prepare signature", "numReceivedSoFar", len(prepareSigs), "validatorID", validatorID, "PublicKeys", len(consensus.PublicKeys))
	prepareSigs[validatorID] = &sign
	prepareBitmap.SetKey(validatorPeer.PubKey, true) // Set the bitmap indicating that this validator signed.

	targetState := PreparedDone
	if len(prepareSigs) >= ((len(consensus.PublicKeys)*2)/3+1) && consensus.state < targetState {
		utils.GetLogInstance().Debug("Enough prepares received with signatures", "num", len(prepareSigs), "state", consensus.state)

		// Construct and broadcast prepared message
		msgToSend, aggSig := consensus.constructPreparedMessage()
		consensus.aggregatedPrepareSig = aggSig

		utils.GetLogInstance().Warn("[Consensus]", "sent prepared message", len(msgToSend))
		consensus.host.SendMessageToGroups([]p2p.GroupID{p2p.GroupIDBeacon}, host.ConstructP2pMessage(byte(17), msgToSend))

		// Set state to targetState
		consensus.state = targetState

		// Leader sign the multi-sig and bitmap (for commit phase)
		multiSigAndBitmap := append(aggSig.Serialize(), prepareBitmap.Bitmap...)
		consensus.commitSigs[consensus.nodeID] = consensus.priKey.SignHash(multiSigAndBitmap)
	}
}

// Processes the commit message sent from validators
func (consensus *Consensus) processCommitMessage(message *msg_pb.Message) {
	consensusMsg := message.GetConsensus()

	validatorID := consensusMsg.SenderId
	commitSig := consensusMsg.Payload

	consensus.mutex.Lock()
	defer consensus.mutex.Unlock()

	validatorPeer := consensus.getValidatorPeerByID(validatorID)

	if validatorPeer == nil {
		utils.GetLogInstance().Error("Invalid validator", "validatorID", validatorID)
		return
	}

	if err := consensus.checkConsensusMessage(message, validatorPeer.PubKey); err != nil {
		utils.GetLogInstance().Debug("Failed to check the validator message", "validatorID", validatorID)
		return
	}

	commitSigs := consensus.commitSigs
	commitBitmap := consensus.commitBitmap

	// proceed only when the message is not received before
	_, ok := commitSigs[validatorID]
	if ok {
		utils.GetLogInstance().Debug("Already received commit message from the validator", "validatorID", validatorID)
		return
	}

	if len((commitSigs)) >= ((len(consensus.PublicKeys)*2)/3 + 1) {
		utils.GetLogInstance().Debug("Received additional new commit message", "validatorID", strconv.Itoa(int(validatorID)))
		return
	}

	// Verify the signature on prepare multi-sig and bitmap is correct
	var sign bls.Sign
	err := sign.Deserialize(commitSig)
	if err != nil {
		utils.GetLogInstance().Debug("Failed to deserialize bls signature", "validatorID", validatorID)
		return
	}
	aggSig := bls_cosi.AggregateSig(consensus.GetPrepareSigsArray())
	if !sign.VerifyHash(validatorPeer.PubKey, append(aggSig.Serialize(), consensus.prepareBitmap.Bitmap...)) {
		utils.GetLogInstance().Error("Received invalid BLS signature", "validatorID", validatorID)
		return
	}

	utils.GetLogInstance().Debug("Received new commit message", "numReceivedSoFar", len(commitSigs), "validatorID", strconv.Itoa(int(validatorID)))
	commitSigs[validatorID] = &sign
	// Set the bitmap indicating that this validator signed.
	commitBitmap.SetKey(validatorPeer.PubKey, true)

	targetState := CommittedDone
	if len(commitSigs) >= ((len(consensus.PublicKeys)*2)/3+1) && consensus.state != targetState {
		utils.GetLogInstance().Info("Enough commits received!", "num", len(commitSigs), "state", consensus.state)

		// Construct and broadcast committed message
		msgToSend, aggSig := consensus.constructCommittedMessage()
		consensus.aggregatedCommitSig = aggSig

		utils.GetLogInstance().Warn("[Consensus]", "sent committed message", len(msgToSend))
		consensus.host.SendMessageToGroups([]p2p.GroupID{p2p.GroupIDBeacon}, host.ConstructP2pMessage(byte(17), msgToSend))

		var blockObj types.Block
		err := rlp.DecodeBytes(consensus.block, &blockObj)
		if err != nil {
			utils.GetLogInstance().Debug("failed to construct the new block after consensus")
		}

		// Sign the block
		copy(blockObj.Header().PrepareSignature[:], consensus.aggregatedPrepareSig.Serialize()[:])
		copy(blockObj.Header().PrepareBitmap[:], consensus.prepareBitmap.Bitmap)
		copy(blockObj.Header().CommitSignature[:], consensus.aggregatedCommitSig.Serialize()[:])
		copy(blockObj.Header().CommitBitmap[:], consensus.commitBitmap.Bitmap)

		consensus.state = targetState

		select {
		case consensus.VerifiedNewBlock <- &blockObj:
		default:
			utils.GetLogInstance().Info("[SYNC] consensus verified block send to chan failed", "blockHash", blockObj.Hash())
		}

		consensus.reportMetrics(blockObj)

		// Dump new block into level db.
		explorer.GetStorageInstance(consensus.leader.IP, consensus.leader.Port, true).Dump(&blockObj, consensus.consensusID)

		// Reset state to Finished, and clear other data.
		consensus.ResetState()
		consensus.consensusID++

		consensus.OnConsensusDone(&blockObj)
		utils.GetLogInstance().Debug("HOORAY!!!!!!! CONSENSUS REACHED!!!!!!!", "consensusID", consensus.consensusID, "numOfSignatures", len(commitSigs))

		// TODO: remove this temporary delay
		time.Sleep(500 * time.Millisecond)
		// Send signal to Node so the new block can be added and new round of consensus can be triggered
		consensus.ReadySignal <- struct{}{}
	}
}

func (consensus *Consensus) reportMetrics(block types.Block) {
	endTime := time.Now()
	timeElapsed := endTime.Sub(startTime)
	numOfTxs := len(block.Transactions())
	tps := float64(numOfTxs) / timeElapsed.Seconds()
	utils.GetLogInstance().Info("TPS Report",
		"numOfTXs", numOfTxs,
		"startTime", startTime,
		"endTime", endTime,
		"timeElapsed", timeElapsed,
		"TPS", tps,
		"consensus", consensus)

	// Post metrics
	profiler := profiler.GetProfiler()
	if profiler.MetricsReportURL == "" {
		return
	}

	txHashes := []string{}
	for i, end := 0, len(block.Transactions()); i < 3 && i < end; i++ {
		txHash := block.Transactions()[end-1-i].Hash()
		txHashes = append(txHashes, hex.EncodeToString(txHash[:]))
	}
	metrics := map[string]interface{}{
		"key":             hex.EncodeToString(consensus.pubKey.Serialize()),
		"tps":             tps,
		"txCount":         numOfTxs,
		"nodeCount":       len(consensus.PublicKeys) + 1,
		"latestBlockHash": hex.EncodeToString(consensus.blockHash[:]),
		"latestTxHashes":  txHashes,
		"blockLatency":    int(timeElapsed / time.Millisecond),
	}
	profiler.LogMetrics(metrics)
}