dcrd/internal/progresslog/logger.go

// Copyright (c) 2015-2021 The Decred developers
// Use of this source code is governed by an ISC
// license that can be found in the LICENSE file.

package progresslog

import (
	"sync"
	"time"

	"github.com/decred/dcrd/wire"
	"github.com/decred/slog"
)

// 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
}

// Logger provides periodic logging of progress towards some action such as
// syncing the chain.
type Logger struct {
	sync.Mutex
	subsystemLogger slog.Logger
	progressAction  string

	// lastLogTime tracks the last time a log statement was shown.
	lastLogTime time.Time

	// These fields accumulate information about blocks between log statements.
	receivedBlocks  uint64
	receivedTxns    uint64
	receivedVotes   uint64
	receivedRevokes uint64
	receivedTickets uint64

	// These fields accumulate information about headers between log statements.
	receivedHeaders uint64
}

// New returns a new block progress logger.
func New(progressAction string, logger slog.Logger) *Logger {
	return &Logger{
		lastLogTime:     time.Now(),
		progressAction:  progressAction,
		subsystemLogger: logger,
	}
}

// LogProgress accumulates details for the provided block and periodically
// (every 10 seconds) logs an information message to show progress to the user
// along with duration and totals included.
//
// The force flag may be used to force a log message to be shown regardless of
// the time the last one was shown.
//
// The progress message is templated as follows:
//  {progressAction} {numProcessed} {blocks|block} in the last {timePeriod}
//  ({numTxs} {transactions|transaction}, {numTickets} {tickets|ticket},
//  {numVotes} {votes|vote}, {numRevocations} {revocations|revocation},
//  height {lastBlockHeight}, progress {progress}%)
//
// This function is safe for concurrent access.
func (l *Logger) LogProgress(block *wire.MsgBlock, forceLog bool, progressFn func() float64) {
	l.Lock()
	defer l.Unlock()

	header := &block.Header
	l.receivedBlocks++
	l.receivedTxns += uint64(len(block.Transactions))
	l.receivedVotes += uint64(header.Voters)
	l.receivedRevokes += uint64(header.Revocations)
	l.receivedTickets += uint64(header.FreshStake)
	now := time.Now()
	duration := now.Sub(l.lastLogTime)
	if !forceLog && duration < time.Second*10 {
		return
	}

	// Log information about chain progress.
	l.subsystemLogger.Infof("%s %d %s in the last %0.2fs (%d %s, %d %s, %d %s, "+
		"%d %s, height %d, progress %0.2f%%)", l.progressAction,
		l.receivedBlocks, pickNoun(l.receivedBlocks, "block", "blocks"),
		duration.Seconds(),
		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, progressFn())

	l.receivedBlocks = 0
	l.receivedTxns = 0
	l.receivedVotes = 0
	l.receivedTickets = 0
	l.receivedRevokes = 0
	l.lastLogTime = now
}

// LogHeaderProgress accumulates the provided number of processed headers and
// periodically (every 10 seconds) logs an information message to show the
// header sync progress to the user along with duration and totals included.
//
// The force flag may be used to force a log message to be shown regardless of
// the time the last one was shown.
//
// The progress message is templated as follows:
//  {progressAction} {numProcessed} {headers|header} in the last {timePeriod}
//  (progress {progress}%)
//
// This function is safe for concurrent access.
func (l *Logger) LogHeaderProgress(processedHeaders uint64, forceLog bool, progressFn func() float64) {
	l.Lock()
	defer l.Unlock()

	l.receivedHeaders += processedHeaders

	now := time.Now()
	duration := now.Sub(l.lastLogTime)
	if !forceLog && duration < time.Second*10 {
		return
	}

	// Log information about header progress.
	l.subsystemLogger.Infof("%s %d %s in the last %0.2fs (progress %0.2f%%)",
		l.progressAction, l.receivedHeaders,
		pickNoun(l.receivedHeaders, "header", "headers"),
		duration.Seconds(), progressFn())

	l.receivedHeaders = 0
	l.lastLogTime = now
}

// SetLastLogTime updates the last time data was logged to the provided time.
//
// This function is safe for concurrent access.
func (l *Logger) SetLastLogTime(time time.Time) {
	l.Lock()
	l.lastLogTime = time
	l.Unlock()
}