From 6c0f08894c3f597252b18a5fe6ae5e0dd73326d2 Mon Sep 17 00:00:00 2001 From: Dave Collins Date: Thu, 10 Dec 2020 12:52:16 -0600 Subject: [PATCH 1/2] progresslog: Make block progress log internal. This splits the block progress logging used by the block manager and dump blockchain option to a separate internal package named progresslog and updates its code to be more consistent with the rest of the code base along the way. This is a part of the overall effort to decouple the block manager from the server so it can be split out into a separate internal netsync package. --- blockdb.go | 5 +- blockmanager.go | 7 +- .../progresslog/blocklogger.go | 67 +++++----- .../progresslog/blocklogger_test.go | 120 +++++++++--------- 4 files changed, 106 insertions(+), 93 deletions(-) rename blocklogger.go => internal/progresslog/blocklogger.go (51%) rename blocklogger_test.go => internal/progresslog/blocklogger_test.go (55%) diff --git a/blockdb.go b/blockdb.go index d3108ef0d3..f3fbaa2cf0 100644 --- a/blockdb.go +++ b/blockdb.go @@ -15,6 +15,7 @@ import ( "github.com/decred/dcrd/blockchain/v4" "github.com/decred/dcrd/chaincfg/v3" "github.com/decred/dcrd/database/v2" + "github.com/decred/dcrd/internal/progresslog" ) const ( @@ -194,7 +195,7 @@ func dumpBlockChain(params *chaincfg.Params, b *blockchain.BlockChain) error { dcrdLog.Infof("Writing the blockchain to flat file %q. This might take a "+ "while...", cfg.DumpBlockchain) - progressLogger := newBlockProgressLogger("Wrote", dcrdLog) + progressLogger := progresslog.New("Wrote", dcrdLog) file, err := os.Create(cfg.DumpBlockchain) if err != nil { @@ -240,7 +241,7 @@ func dumpBlockChain(params *chaincfg.Params, b *blockchain.BlockChain) error { return err } - progressLogger.logBlockHeight(bl, tipHeight) + progressLogger.LogBlockHeight(bl.MsgBlock(), tipHeight) } bmgrLog.Infof("Successfully dumped the blockchain (%v blocks) to %v.", diff --git a/blockmanager.go b/blockmanager.go index dae19f8ff2..e1764436a4 100644 --- a/blockmanager.go +++ b/blockmanager.go @@ -22,6 +22,7 @@ import ( "github.com/decred/dcrd/internal/fees" "github.com/decred/dcrd/internal/mempool" "github.com/decred/dcrd/internal/mining" + "github.com/decred/dcrd/internal/progresslog" "github.com/decred/dcrd/internal/rpcserver" peerpkg "github.com/decred/dcrd/peer/v2" "github.com/decred/dcrd/txscript/v3" @@ -306,7 +307,7 @@ type blockManager struct { rejectedTxns map[chainhash.Hash]struct{} requestedTxns map[chainhash.Hash]struct{} requestedBlocks map[chainhash.Hash]struct{} - progressLogger *blockProgressLogger + progressLogger *progresslog.BlockLogger syncPeer *peerpkg.Peer msgChan chan interface{} wg sync.WaitGroup @@ -1115,7 +1116,7 @@ func (b *blockManager) handleBlockMsg(bmsg *blockMsg) { } else { // When the block is not an orphan, log information about it and // update the chain state. - b.progressLogger.logBlockHeight(bmsg.block, b.SyncHeight()) + b.progressLogger.LogBlockHeight(bmsg.block.MsgBlock(), b.SyncHeight()) if onMainChain { // Notify stake difficulty subscribers and prune invalidated @@ -2462,7 +2463,7 @@ func newBlockManager(config *blockManagerConfig) (*blockManager, error) { requestedTxns: make(map[chainhash.Hash]struct{}), requestedBlocks: make(map[chainhash.Hash]struct{}), peerStates: make(map[*peerpkg.Peer]*peerSyncState), - progressLogger: newBlockProgressLogger("Processed", bmgrLog), + progressLogger: progresslog.New("Processed", bmgrLog), msgChan: make(chan interface{}, config.MaxPeers*3), headerList: list.New(), quit: make(chan struct{}), diff --git a/blocklogger.go b/internal/progresslog/blocklogger.go similarity index 51% rename from blocklogger.go rename to internal/progresslog/blocklogger.go index e136946c05..d0274880a7 100644 --- a/blocklogger.go +++ b/internal/progresslog/blocklogger.go @@ -1,59 +1,64 @@ -// Copyright (c) 2015-2019 The Decred developers +// Copyright (c) 2015-2020 The Decred developers // Use of this source code is governed by an ISC // license that can be found in the LICENSE file. -package main +package progresslog import ( "sync" "time" - "github.com/decred/dcrd/dcrutil/v3" + "github.com/decred/dcrd/wire" "github.com/decred/slog" ) -// blockProgressLogger provides periodic logging for other services in order -// to show users progress of certain "actions" involving some or all current -// blocks. Ex: syncing to best chain, indexing all blocks, etc. -type blockProgressLogger struct { +// BlockLogger provides periodic logging for other services in order to show +// users progress of certain "actions" involving some or all current blocks. +// For example, syncing to best chain, indexing all blocks, etc. +type BlockLogger struct { + sync.Mutex + subsystemLogger slog.Logger + progressAction string + receivedLogBlocks int64 receivedLogTx int64 receivedLogVotes int64 receivedLogRevocations int64 receivedLogTickets int64 lastBlockLogTime time.Time - - subsystemLogger slog.Logger - progressAction string - sync.Mutex } -// newBlockProgressLogger returns a new block progress logger. +// New returns a new block progress logger. +// // The progress message is templated as follows: // {progressAction} {numProcessed} {blocks|block} in the last {timePeriod} -// ({numTxs}, height {lastBlockHeight}, {lastBlockTimeStamp}) -func newBlockProgressLogger(progressMessage string, logger slog.Logger) *blockProgressLogger { - return &blockProgressLogger{ +// ({numTxs} {transactions|transaction}, {numTickets} {tickets|ticket}, +// {numVotes} {votes|vote}, {numRevocations} {revocations|revocation}, +// height {lastBlockHeight}, {lastBlockTimeStamp}) +func New(progressMessage string, logger slog.Logger) *BlockLogger { + return &BlockLogger{ lastBlockLogTime: time.Now(), progressAction: progressMessage, subsystemLogger: logger, } } -// logBlockHeight logs a new block height as an information message to show -// progress to the user. In order to prevent spam, it limits logging to one +// LogBlockHeight logs a new block height as an information message to show +// progress to the user. In order to prevent spam, it limits logging to one // message every 10 seconds with duration and totals included. -func (b *blockProgressLogger) logBlockHeight(block *dcrutil.Block, syncHeight int64) { +func (b *BlockLogger) LogBlockHeight(block *wire.MsgBlock, syncHeight int64) { b.Lock() defer b.Unlock() + + header := &block.Header b.receivedLogBlocks++ - b.receivedLogTx += int64(len(block.MsgBlock().Transactions)) - b.receivedLogVotes += int64(block.MsgBlock().Header.Voters) - b.receivedLogRevocations += int64(block.MsgBlock().Header.Revocations) - b.receivedLogTickets += int64(block.MsgBlock().Header.FreshStake) + b.receivedLogTx += int64(len(block.Transactions)) + b.receivedLogVotes += int64(header.Voters) + b.receivedLogRevocations += int64(header.Revocations) + b.receivedLogTickets += int64(header.FreshStake) now := time.Now() duration := now.Sub(b.lastBlockLogTime) - if block.Height() < syncHeight && duration < time.Second*10 { + if int64(header.Height) < syncHeight && duration < time.Second*10 { return } @@ -82,12 +87,11 @@ func (b *blockProgressLogger) logBlockHeight(block *dcrutil.Block, syncHeight in if b.receivedLogVotes == 1 { voteStr = "vote" } - b.subsystemLogger.Infof("%s %d %s in the last %s (%d %s, %d %s, %d %s, %d %s, height "+ - "%d, %s)", - b.progressAction, b.receivedLogBlocks, blockStr, tDuration, - b.receivedLogTx, txStr, b.receivedLogTickets, ticketStr, - b.receivedLogVotes, voteStr, b.receivedLogRevocations, - revocationStr, block.Height(), block.MsgBlock().Header.Timestamp) + b.subsystemLogger.Infof("%s %d %s in the last %s (%d %s, %d %s, %d %s, "+ + "%d %s, height %d, %s)", b.progressAction, b.receivedLogBlocks, + blockStr, tDuration, b.receivedLogTx, txStr, b.receivedLogTickets, + ticketStr, b.receivedLogVotes, voteStr, b.receivedLogRevocations, + revocationStr, header.Height, header.Timestamp) b.receivedLogBlocks = 0 b.receivedLogTx = 0 @@ -97,6 +101,9 @@ func (b *blockProgressLogger) logBlockHeight(block *dcrutil.Block, syncHeight in b.lastBlockLogTime = now } -func (b *blockProgressLogger) SetLastLogTime(time time.Time) { +// SetLastLogTime updates the last time data was logged to the provided time. +func (b *BlockLogger) SetLastLogTime(time time.Time) { + b.Lock() b.lastBlockLogTime = time + b.Unlock() } diff --git a/blocklogger_test.go b/internal/progresslog/blocklogger_test.go similarity index 55% rename from blocklogger_test.go rename to internal/progresslog/blocklogger_test.go index b5c5207a3d..e640134296 100644 --- a/blocklogger_test.go +++ b/internal/progresslog/blocklogger_test.go @@ -2,22 +2,65 @@ // Use of this source code is governed by an ISC // license that can be found in the LICENSE file. -package main +package progresslog import ( + "io/ioutil" "reflect" "testing" "time" - "github.com/decred/dcrd/dcrutil/v3" "github.com/decred/dcrd/wire" + "github.com/decred/slog" ) +var ( + backendLog = slog.NewBackend(ioutil.Discard) + testLog = backendLog.Logger("TEST") +) + +// TestLogBlockHeight ensures the logging functionality works as expected via +// a test logger. func TestLogBlockHeight(t *testing.T) { + testBlocks := []wire.MsgBlock{{ + Header: wire.BlockHeader{ + Version: 1, + Height: 100000, + Timestamp: time.Unix(1293623863, 0), // 2010-12-29 11:57:43 +0000 UTC + Voters: 2, + Revocations: 1, + FreshStake: 4, + }, + Transactions: make([]*wire.MsgTx, 4), + STransactions: nil, + }, { + Header: wire.BlockHeader{ + Version: 1, + Height: 100001, + Timestamp: time.Unix(1293624163, 0), // 2010-12-29 12:02:43 +0000 UTC + Voters: 3, + Revocations: 2, + FreshStake: 2, + }, + Transactions: make([]*wire.MsgTx, 2), + STransactions: nil, + }, { + Header: wire.BlockHeader{ + Version: 1, + Height: 100002, + Timestamp: time.Unix(1293624463, 0), // 2010-12-29 12:07:43 +0000 UTC + Voters: 1, + Revocations: 3, + FreshStake: 1, + }, + Transactions: make([]*wire.MsgTx, 3), + STransactions: nil, + }} + tests := []struct { name string reset bool - inputBlock *dcrutil.Block + inputBlock *wire.MsgBlock inputSyncHeight int64 inputLastLogTime time.Time wantReceivedLogBlocks int64 @@ -26,8 +69,8 @@ func TestLogBlockHeight(t *testing.T) { wantReceivedLogRevocations int64 wantReceivedLogTickets int64 }{{ - name: "TestLogBlockHeight with last log time < 10 seconds ago and sync height not reached", - inputBlock: dcrutil.NewBlock(&TestBlock100000), + name: "round 1, block 0, last log time < 10 secs ago, < sync height", + inputBlock: &testBlocks[0], inputSyncHeight: 100002, inputLastLogTime: time.Now(), wantReceivedLogBlocks: 1, @@ -36,8 +79,8 @@ func TestLogBlockHeight(t *testing.T) { wantReceivedLogRevocations: 1, wantReceivedLogTickets: 4, }, { - name: "TestLogBlockHeight with last log time < 10 seconds ago and sync height not reached", - inputBlock: dcrutil.NewBlock(&TestBlock100001), + name: "round 1, block 1, last log time < 10 secs ago, < sync height", + inputBlock: &testBlocks[1], inputSyncHeight: 100002, inputLastLogTime: time.Now(), wantReceivedLogBlocks: 2, @@ -46,8 +89,8 @@ func TestLogBlockHeight(t *testing.T) { wantReceivedLogRevocations: 3, wantReceivedLogTickets: 6, }, { - name: "TestLogBlockHeight with last log time < 10 seconds ago and sync height reached", - inputBlock: dcrutil.NewBlock(&TestBlock100002), + name: "round 1, block 2, last log time < 10 secs ago, < sync height", + inputBlock: &testBlocks[2], inputSyncHeight: 100002, inputLastLogTime: time.Now(), wantReceivedLogBlocks: 0, @@ -56,9 +99,9 @@ func TestLogBlockHeight(t *testing.T) { wantReceivedLogRevocations: 0, wantReceivedLogTickets: 0, }, { - name: "TestLogBlockHeight with last log time < 10 seconds ago and sync height not reached", + name: "round 2, block 0, last log time < 10 secs ago, < sync height", reset: true, - inputBlock: dcrutil.NewBlock(&TestBlock100000), + inputBlock: &testBlocks[0], inputSyncHeight: 100002, inputLastLogTime: time.Now(), wantReceivedLogBlocks: 1, @@ -67,8 +110,8 @@ func TestLogBlockHeight(t *testing.T) { wantReceivedLogRevocations: 1, wantReceivedLogTickets: 4, }, { - name: "TestLogBlockHeight with last log time > 10 seconds ago and sync height not reached", - inputBlock: dcrutil.NewBlock(&TestBlock100001), + name: "round 2, block 1, last log time > 10 secs ago, < sync height", + inputBlock: &testBlocks[1], inputSyncHeight: 100002, inputLastLogTime: time.Now().Add(-11 * time.Second), wantReceivedLogBlocks: 0, @@ -77,8 +120,8 @@ func TestLogBlockHeight(t *testing.T) { wantReceivedLogRevocations: 0, wantReceivedLogTickets: 0, }, { - name: "TestLogBlockHeight with last log time > 10 seconds ago and sync height reached", - inputBlock: dcrutil.NewBlock(&TestBlock100002), + name: "round 2, block 2, last log time > 10 secs ago, == sync height", + inputBlock: &testBlocks[2], inputSyncHeight: 100002, inputLastLogTime: time.Now().Add(-11 * time.Second), wantReceivedLogBlocks: 0, @@ -88,14 +131,14 @@ func TestLogBlockHeight(t *testing.T) { wantReceivedLogTickets: 0, }} - progressLogger := newBlockProgressLogger("Written", bmgrLog) + progressLogger := New("Wrote", testLog) for _, test := range tests { if test.reset { - progressLogger = newBlockProgressLogger("Written", bmgrLog) + progressLogger = New("Wrote", testLog) } progressLogger.SetLastLogTime(test.inputLastLogTime) - progressLogger.logBlockHeight(test.inputBlock, test.inputSyncHeight) - wantBlockProgressLogger := &blockProgressLogger{ + progressLogger.LogBlockHeight(test.inputBlock, test.inputSyncHeight) + wantBlockProgressLogger := &BlockLogger{ receivedLogBlocks: test.wantReceivedLogBlocks, receivedLogTx: test.wantReceivedLogTx, receivedLogVotes: test.wantReceivedLogVotes, @@ -111,42 +154,3 @@ func TestLogBlockHeight(t *testing.T) { } } } - -var TestBlock100000 = wire.MsgBlock{ - Header: wire.BlockHeader{ - Version: 1, - Height: 100000, - Timestamp: time.Unix(1293623863, 0), // 2010-12-29 11:57:43 +0000 UTC - Voters: 2, - Revocations: 1, - FreshStake: 4, - }, - Transactions: []*wire.MsgTx{{}, {}, {}, {}}, - STransactions: []*wire.MsgTx{}, -} - -var TestBlock100001 = wire.MsgBlock{ - Header: wire.BlockHeader{ - Version: 1, - Height: 100001, - Timestamp: time.Unix(1293624163, 0), // 2010-12-29 12:02:43 +0000 UTC - Voters: 3, - Revocations: 2, - FreshStake: 2, - }, - Transactions: []*wire.MsgTx{{}, {}}, - STransactions: []*wire.MsgTx{}, -} - -var TestBlock100002 = wire.MsgBlock{ - Header: wire.BlockHeader{ - Version: 1, - Height: 100002, - Timestamp: time.Unix(1293624463, 0), // 2010-12-29 12:07:43 +0000 UTC - Voters: 1, - Revocations: 3, - FreshStake: 1, - }, - Transactions: []*wire.MsgTx{{}, {}, {}}, - STransactions: []*wire.MsgTx{}, -} From 7a809399abb7a7196570f7d6cb93ddc2ae1adc02 Mon Sep 17 00:00:00 2001 From: Dave Collins Date: Thu, 10 Dec 2020 12:52:20 -0600 Subject: [PATCH 2/2] progresslog: Add package documentation. --- internal/progresslog/README.md | 26 ++++++++++++++++++++++++++ internal/progresslog/doc.go | 21 +++++++++++++++++++++ 2 files changed, 47 insertions(+) create mode 100644 internal/progresslog/README.md create mode 100644 internal/progresslog/doc.go diff --git a/internal/progresslog/README.md b/internal/progresslog/README.md new file mode 100644 index 0000000000..30fc1d293a --- /dev/null +++ b/internal/progresslog/README.md @@ -0,0 +1,26 @@ +progresslog +=========== + +[![Build Status](https://github.com/decred/dcrd/workflows/Build%20and%20Test/badge.svg)](https://github.com/decred/dcrd/actions) +[![ISC License](https://img.shields.io/badge/license-ISC-blue.svg)](http://copyfree.org) +[![Doc](https://img.shields.io/badge/doc-reference-blue.svg)](https://pkg.go.dev/github.com/decred/dcrd/internal/progresslog) + +Package progresslog provides periodic logging for block processing. + +Tests are included to ensure proper functionality. + +## Feature Overview + +- Maintains cumulative totals about blocks between each logging interval + - Total number of blocks + - Total number of transactions + - Total number of votes + - Total number of tickets + - Total number of revocations +- Logs all cumulative data every 10 seconds +- Immediately logs any outstanding data when the provided sync height is reached + +## License + +Package progresslog is licensed under the [copyfree](http://copyfree.org) ISC +License. diff --git a/internal/progresslog/doc.go b/internal/progresslog/doc.go new file mode 100644 index 0000000000..0758a3b653 --- /dev/null +++ b/internal/progresslog/doc.go @@ -0,0 +1,21 @@ +// Copyright (c) 2020 The Decred developers +// Use of this source code is governed by an ISC +// license that can be found in the LICENSE file. + +/* +Package progresslog provides periodic logging for block processing. + +Tests are included to ensure proper functionality. + +## Feature Overview + +- Maintains cumulative totals about blocks between each logging interval + - Total number of blocks + - Total number of transactions + - Total number of votes + - Total number of tickets + - Total number of revocations +- Logs all cumulative data every 10 seconds +- Immediately logs any outstanding data when the provided sync height is reached +*/ +package progresslog