multi: Add chain verify progress percentage.

This modifies blockchain, progresslog, and netsync to provide a progress
percentage when logging the main chain verification process.

A new method is added to blockchain that determines the verification
progress of the current best chain based on how far along it towards the
best known header and blockchain is also modified to log the
verification progress in the initial chain state message when the
blockchain is first loaded.

In addition, the progess logger is modified to log the verification
progress instead of the timestamp of the last block and the netsync code
is updated to make use of the new verification progress func per above.

Finally, the netsync code now determines when the chain is considered
current and logs new blocks as they are connected along with their hash
and additional details.  This provides a cleaner distinction between the
initial verification and catchup phase and steady state operation.

blockchain/chain.go

@@ -2221,8 +2221,9 @@ func New(ctx context.Context, config *Config) (*BlockChain, error) {
 		bestHdr.hash)
 
 	tip := b.bestChain.Tip()
-	log.Infof("Chain state: height %d, hash %v, total transactions %d, work %v",
-		tip.height, tip.hash, b.stateSnapshot.TotalTxns, tip.workSum)
+	log.Infof("Chain state: height %d, hash %v, total transactions %d, work "+
+		"%v, progress %0.2f%%", tip.height, tip.hash,
+		b.stateSnapshot.TotalTxns, tip.workSum, b.VerifyProgress())
 
 	return &b, nil
 }

blockchain/chainquery.go

@@ -6,6 +6,7 @@ package blockchain
 
 import (
 	"bytes"
+	"math"
 	"sort"
 
 	"github.com/decred/dcrd/chaincfg/chainhash"
@@ -233,3 +234,19 @@ func (b *BlockChain) NextNeededBlocks(maxResults uint8, exclude map[chainhash.Ha
 	}
 	return neededBlocks
 }
+
+// VerifyProgress returns a percentage that is a guess of the progress of the
+// chain verification process.
+//
+// This function is safe for concurrent access.
+func (b *BlockChain) VerifyProgress() float64 {
+	b.index.RLock()
+	bestHdr := b.index.bestHeader
+	b.index.RUnlock()
+	if bestHdr.height == 0 {
+		return 0.0
+	}
+
+	tip := b.bestChain.Tip()
+	return math.Min(float64(tip.height)/float64(bestHdr.height), 1.0) * 100
+}

blockdb.go

@@ -240,7 +240,9 @@ func dumpBlockChain(params *chaincfg.Params, b *blockchain.BlockChain) error {
 
 		msgBlock := bl.MsgBlock()
 		forceLog := int64(msgBlock.Header.Height) >= tipHeight
-		progressLogger.LogProgress(msgBlock, forceLog)
+		progressLogger.LogProgress(msgBlock, forceLog, func() float64 {
+			return float64(msgBlock.Header.Height) / float64(tipHeight) * 100
+		})
 	}
 
 	srvrLog.Infof("Successfully dumped the blockchain (%v blocks) to %v.",

internal/netsync/log.go

@@ -1,4 +1,4 @@
-// Copyright (c) 2020 The Decred developers
+// Copyright (c) 2020-2021 The Decred developers
 // Use of this source code is governed by an ISC
 // license that can be found in the LICENSE file.
 
@@ -20,3 +20,12 @@ var log = slog.Disabled
 func UseLogger(logger slog.Logger) {
 	log = logger
 }
+
+// pickNoun returns the singular or plural form of a noun depending on the
+// provided count.
+func pickNoun(n uint64, singular, plural string) string {
+	if n == 1 {
+		return singular
+	}
+	return plural
+}

internal/netsync/manager.go

@@ -781,6 +781,11 @@ func (m *SyncManager) handleBlockMsg(bmsg *blockMsg) {
 		return
 	}
 
+	// Save whether or not the chain believes it is current prior to processing
+	// the block for use below in determining logging behavior.
+	chain := m.cfg.Chain
+	wasChainCurrent := chain.IsCurrent()
+
 	// Process the block to include validation, best chain selection, etc.
 	//
 	// Also, remove the block from the request maps once it has been processed.
@@ -819,15 +824,39 @@ func (m *SyncManager) handleBlockMsg(bmsg *blockMsg) {
 		return
 	}
 
-	// Log information about the block and update the chain state.
+	// Log information about the block.  Use the progress logger when the chain
+	// was not already current prior to processing the block to provide nicer
+	// periodic logging with a progress percentage.  Otherwise, log the block
+	// individually along with some stats.
 	msgBlock := bmsg.block.MsgBlock()
-	forceLog := int64(msgBlock.Header.Height) >= m.SyncHeight()
-	m.progressLogger.LogProgress(msgBlock, forceLog)
-
+	header := &msgBlock.Header
+	if !wasChainCurrent {
+		forceLog := int64(header.Height) >= m.SyncHeight()
+		m.progressLogger.LogProgress(msgBlock, forceLog, chain.VerifyProgress)
+		if chain.IsCurrent() {
+			best := chain.BestSnapshot()
+			log.Infof("Initial chain sync complete (hash %s, height %d)",
+				best.Hash, best.Height)
+		}
+	} else {
+		numTxns := uint64(len(msgBlock.Transactions))
+		numTickets := uint64(header.FreshStake)
+		numVotes := uint64(header.Voters)
+		numRevokes := uint64(header.Revocations)
+		log.Infof("New block %s (%d %s, %d %s, %d %s, %d %s, height %d)",
+			blockHash, numTxns, pickNoun(numTxns, "transaction", "transactions"),
+			numTickets, pickNoun(numTickets, "ticket", "tickets"),
+			numVotes, pickNoun(numVotes, "vote", "votes"),
+			numRevokes, pickNoun(numRevokes, "revocation", "revocations"),
+			header.Height)
+	}
+
+	// Perform some additional processing when the block extended the main
+	// chain.
 	onMainChain := forkLen == 0
 	if onMainChain {
 		// Prune invalidated transactions.
-		best := m.cfg.Chain.BestSnapshot()
+		best := chain.BestSnapshot()
 		m.cfg.TxMemPool.PruneStakeTx(best.NextStakeDiff, best.Height)
 		m.cfg.TxMemPool.PruneExpiredTx()
 
@@ -842,7 +871,7 @@ func (m *SyncManager) handleBlockMsg(bmsg *blockMsg) {
 	// the main chain, update the heights of other peers whose invs may have
 	// been ignored when actively syncing while the chain was not yet current or
 	// lost the lock announcement race.
-	blockHeight := int64(bmsg.block.MsgBlock().Header.Height)
+	blockHeight := int64(header.Height)
 	peer.UpdateLastBlockHeight(blockHeight)
 	if onMainChain && m.IsCurrent() {
 		for _, p := range m.peers {
@@ -1091,6 +1120,11 @@ func (m *SyncManager) handleHeadersMsg(hmsg *headersMsg) {
 			// that the headers are synced.
 			chain.MaybeUpdateIsCurrent()
 			isChainCurrent = chain.IsCurrent()
+			if isChainCurrent {
+				best := chain.BestSnapshot()
+				log.Infof("Initial chain sync complete (hash %s, height %d)",
+					best.Hash, best.Height)
+			}
 		}
 	}
 

internal/progresslog/logger.go

@@ -62,8 +62,8 @@ func New(progressAction string, logger slog.Logger) *Logger {
 //  {progressAction} {numProcessed} {blocks|block} in the last {timePeriod}
 //  ({numTxs} {transactions|transaction}, {numTickets} {tickets|ticket},
 //  {numVotes} {votes|vote}, {numRevocations} {revocations|revocation},
-//  height {lastBlockHeight}, {lastBlockTimeStamp})
-func (l *Logger) LogProgress(block *wire.MsgBlock, forceLog bool) {
+//  height {lastBlockHeight}, progress {progress}%)
+func (l *Logger) LogProgress(block *wire.MsgBlock, forceLog bool, progressFn func() float64) {
 	l.Lock()
 	defer l.Unlock()
 
@@ -81,14 +81,14 @@ func (l *Logger) LogProgress(block *wire.MsgBlock, forceLog bool) {
 
 	// Log information about chain progress.
 	l.subsystemLogger.Infof("%s %d %s in the last %s (%d %s, %d %s, %d %s, "+
-		"%d %s, height %d, %s)", l.progressAction,
+		"%d %s, height %d, progress %0.2f%%)", l.progressAction,
 		l.receivedBlocks, pickNoun(l.receivedBlocks, "block", "blocks"),
 		duration.Truncate(time.Millisecond*10),
 		l.receivedTxns, pickNoun(l.receivedTxns, "transaction", "transactions"),
 		l.receivedTickets, pickNoun(l.receivedTickets, "ticket", "tickets"),
 		l.receivedVotes, pickNoun(l.receivedVotes, "vote", "votes"),
 		l.receivedRevokes, pickNoun(l.receivedRevokes, "revocation", "revocations"),
-		header.Height, header.Timestamp)
+		header.Height, progressFn())
 
 	l.receivedBlocks = 0
 	l.receivedTxns = 0
@@ -107,7 +107,7 @@ func (l *Logger) LogProgress(block *wire.MsgBlock, forceLog bool) {
 //
 // The progress message is templated as follows:
 //  {progressAction} {numProcessed} {headers|header} in the last {timePeriod}
-//  (progress ~{progress}%)
+//  (progress {progress}%)
 func (l *Logger) LogHeaderProgress(processedHeaders uint64, forceLog bool, progressFn func() float64) {
 	l.receivedHeaders += processedHeaders
 

internal/progresslog/logger_test.go

@@ -131,13 +131,14 @@ func TestLogProgress(t *testing.T) {
 		wantReceivedTickets: 0,
 	}}
 
+	progressFn := func() float64 { return 0.0 }
 	progressLogger := New("Wrote", testLog)
 	for _, test := range tests {
 		if test.reset {
 			progressLogger = New("Wrote", testLog)
 		}
 		progressLogger.SetLastLogTime(test.inputLastLogTime)
-		progressLogger.LogProgress(test.inputBlock, test.forceLog)
+		progressLogger.LogProgress(test.inputBlock, test.forceLog, progressFn)
 		wantBlockProgressLogger := &Logger{
 			receivedBlocks:  test.wantReceivedBlocks,
 			receivedTxns:    test.wantReceivedTxns,