eth, core: track block propagation (#1078)

* eth, core: track block announcement and import timings

* eth: track total delay

* eth: add more context and prefix in logs

* eth/fetcher: fix invalid tracking of received at time

* put logs behind log.enable-block-tracking flag

* fix lint

* improve logging

* add comments

* add comments

builder/files/config.toml

@@ -25,6 +25,7 @@ syncmode = "full"
   # json = false
   # backtrace = ""
   # debug = true
+  # enable-block-tracking = false
 
 [p2p]
   # maxpeers = 1

core/types/block.go

@@ -263,6 +263,7 @@ type Block struct {
 	// inter-peer block relay.
 	ReceivedAt   time.Time
 	ReceivedFrom interface{}
+	AnnouncedAt  *time.Time
 }
 
 // "external" block encoding. used for eth protocol, etc.

docs/cli/example_config.toml

@@ -27,7 +27,8 @@ devfakeauthor = false           # Run miner without validator set authorization
   vmodule = ""                    # Per-module verbosity: comma-separated list of <pattern>=<level> (e.g. eth/*=5,p2p=4)
   json = false                    # Format logs with JSON
   backtrace = ""                  # Request a stack trace at a specific logging statement (e.g. "block.go:271")
-  debug = true       # Prepends log messages with call-site location (file and line number)  -  {requires some effort}
+  debug = true                    # Prepends log messages with call-site location (file and line number)
+  enable-block-tracking = false   # Enables additional logging of information collected while tracking block lifecycle
 
 [p2p]
   maxpeers = 50           # Maximum number of network peers (network disabled if set to 0)

docs/cli/server.md

@@ -204,6 +204,8 @@ The ```bor server``` command runs the Bor client.
 
 - ```log.debug```: Prepends log messages with call-site location (file and line number) (default: false)
 
+- ```log.enable-block-tracking```: Enables additional logging of information collected while tracking block lifecycle (default: false)
+
 - ```log.json```: Format logs with JSON (default: false)
 
 - ```vmodule```: Per-module verbosity: comma-separated list of <pattern>=<level> (e.g. eth/*=5,p2p=4)

eth/backend.go

@@ -284,6 +284,7 @@ func New(stack *node.Node, config *ethconfig.Config) (*Ethereum, error) {
 		EthAPI:              blockChainAPI,
 		checker:             checker,
 		txArrivalWait:       eth.p2pServer.TxArrivalWait,
+		enableBlockTracking: eth.config.EnableBlockTracking,
 	}); err != nil {
 		return nil, err
 	}

eth/ethconfig/config.go

@@ -204,6 +204,9 @@ type Config struct {
 
 	// OverrideVerkle (TODO: remove after the fork)
 	OverrideVerkle *big.Int `toml:",omitempty"`
+
+	// EnableBlockTracking allows logging of information collected while tracking block lifecycle
+	EnableBlockTracking bool
 }
 
 // CreateConsensusEngine creates a consensus engine for the given chain configuration.

eth/fetcher/block_fetcher.go

@@ -117,6 +117,7 @@ type headerFilterTask struct {
 	peer          string          // The source peer of block headers
 	headers       []*types.Header // Collection of headers to filter
 	time          time.Time       // Arrival time of the headers
+	announcedTime time.Time       // Announcement time of the availability of the block
 }
 
 // bodyFilterTask represents a batch of block bodies (transactions and uncles)
@@ -126,6 +127,7 @@ type bodyFilterTask struct {
 	transactions  [][]*types.Transaction // Collection of transactions per block bodies
 	uncles        [][]*types.Header      // Collection of uncles per block bodies
 	time          time.Time              // Arrival time of the blocks' contents
+	announcedTime time.Time              // Announcement time of the availability of the block
 }
 
 // blockOrHeaderInject represents a schedules import operation.
@@ -197,10 +199,13 @@ type BlockFetcher struct {
 	fetchingHook       func([]common.Hash)               // Method to call upon starting a block (eth/61) or header (eth/62) fetch
 	completingHook     func([]common.Hash)               // Method to call upon starting a block body fetch (eth/62)
 	importedHook       func(*types.Header, *types.Block) // Method to call upon successful header or block import (both eth/61 and eth/62)
+
+	// Logging
+	enableBlockTracking bool // Whether to log information collected while tracking block lifecycle
 }
 
 // NewBlockFetcher creates a block fetcher to retrieve blocks based on hash announcements.
-func NewBlockFetcher(light bool, getHeader HeaderRetrievalFn, getBlock blockRetrievalFn, verifyHeader headerVerifierFn, broadcastBlock blockBroadcasterFn, chainHeight chainHeightFn, insertHeaders headersInsertFn, insertChain chainInsertFn, dropPeer peerDropFn) *BlockFetcher {
+func NewBlockFetcher(light bool, getHeader HeaderRetrievalFn, getBlock blockRetrievalFn, verifyHeader headerVerifierFn, broadcastBlock blockBroadcasterFn, chainHeight chainHeightFn, insertHeaders headersInsertFn, insertChain chainInsertFn, dropPeer peerDropFn, enableBlockTracking bool) *BlockFetcher {
 	return &BlockFetcher{
 		light:               light,
 		notify:              make(chan *blockAnnounce),
@@ -225,6 +230,7 @@ func NewBlockFetcher(light bool, getHeader HeaderRetrievalFn, getBlock blockRetr
 		insertHeaders:       insertHeaders,
 		insertChain:         insertChain,
 		dropPeer:            dropPeer,
+		enableBlockTracking: enableBlockTracking,
 	}
 }
 
@@ -276,7 +282,7 @@ func (f *BlockFetcher) Enqueue(peer string, block *types.Block) error {
 
 // FilterHeaders extracts all the headers that were explicitly requested by the fetcher,
 // returning those that should be handled differently.
-func (f *BlockFetcher) FilterHeaders(peer string, headers []*types.Header, time time.Time) []*types.Header {
+func (f *BlockFetcher) FilterHeaders(peer string, headers []*types.Header, time time.Time, announcedAt time.Time) []*types.Header {
 	log.Trace("Filtering headers", "peer", peer, "headers", len(headers))
 
 	// Send the filter channel to the fetcher
@@ -289,7 +295,7 @@ func (f *BlockFetcher) FilterHeaders(peer string, headers []*types.Header, time
 	}
 	// Request the filtering of the header list
 	select {
-	case filter <- &headerFilterTask{peer: peer, headers: headers, time: time}:
+	case filter <- &headerFilterTask{peer: peer, headers: headers, time: time, announcedTime: announcedAt}:
 	case <-f.quit:
 		return nil
 	}
@@ -304,7 +310,7 @@ func (f *BlockFetcher) FilterHeaders(peer string, headers []*types.Header, time
 
 // FilterBodies extracts all the block bodies that were explicitly requested by
 // the fetcher, returning those that should be handled differently.
-func (f *BlockFetcher) FilterBodies(peer string, transactions [][]*types.Transaction, uncles [][]*types.Header, time time.Time) ([][]*types.Transaction, [][]*types.Header) {
+func (f *BlockFetcher) FilterBodies(peer string, transactions [][]*types.Transaction, uncles [][]*types.Header, time time.Time, announcedAt time.Time) ([][]*types.Transaction, [][]*types.Header) {
 	log.Trace("Filtering bodies", "peer", peer, "txs", len(transactions), "uncles", len(uncles))
 
 	// Send the filter channel to the fetcher
@@ -317,7 +323,7 @@ func (f *BlockFetcher) FilterBodies(peer string, transactions [][]*types.Transac
 	}
 	// Request the filtering of the body list
 	select {
-	case filter <- &bodyFilterTask{peer: peer, transactions: transactions, uncles: uncles, time: time}:
+	case filter <- &bodyFilterTask{peer: peer, transactions: transactions, uncles: uncles, time: time, announcedTime: announcedAt}:
 	case <-f.quit:
 		return nil, nil
 	}
@@ -480,7 +486,7 @@ func (f *BlockFetcher) loop() {
 				log.Trace("Fetching scheduled headers", "peer", peer, "list", hashes)
 
 				// Create a closure of the fetch and schedule in on a new thread
-				fetchHeader, hashes := f.fetching[hashes[0]].fetchHeader, hashes
+				fetchHeader, hashes, announcedAt := f.fetching[hashes[0]].fetchHeader, hashes, f.fetching[hashes[0]].time
 				go func(peer string) {
 					if f.fetchingHook != nil {
 						f.fetchingHook(hashes)
@@ -504,7 +510,7 @@ func (f *BlockFetcher) loop() {
 							select {
 							case res := <-resCh:
 								res.Done <- nil
-								f.FilterHeaders(peer, *res.Res.(*eth.BlockHeadersPacket), time.Now().Add(res.Time))
+								f.FilterHeaders(peer, *res.Res.(*eth.BlockHeadersPacket), time.Now(), announcedAt)
 
 							case <-timeout.C:
 								// The peer didn't respond in time. The request
@@ -547,6 +553,7 @@ func (f *BlockFetcher) loop() {
 
 				fetchBodies := f.completing[hashes[0]].fetchBodies
 				bodyFetchMeter.Mark(int64(len(hashes)))
+				announcedAt := f.completing[hashes[0]].time
 
 				go func(peer string, hashes []common.Hash) {
 					resCh := make(chan *eth.Response)
@@ -565,7 +572,7 @@ func (f *BlockFetcher) loop() {
 						res.Done <- nil
 						// Ignoring withdrawals here, since the block fetcher is not used post-merge.
 						txs, uncles, _ := res.Res.(*eth.BlockBodiesPacket).Unpack()
-						f.FilterBodies(peer, txs, uncles, time.Now())
+						f.FilterBodies(peer, txs, uncles, time.Now(), announcedAt)
 
 					case <-timeout.C:
 						// The peer didn't respond in time. The request
@@ -631,6 +638,7 @@ func (f *BlockFetcher) loop() {
 
 							block := types.NewBlockWithHeader(header)
 							block.ReceivedAt = task.time
+							block.AnnouncedAt = &task.announcedTime
 
 							complete = append(complete, block)
 							f.completing[hash] = announce
@@ -725,6 +733,7 @@ func (f *BlockFetcher) loop() {
 						if f.getBlock(hash) == nil {
 							block := types.NewBlockWithHeader(announce.header).WithBody(task.transactions[i], task.uncles[i])
 							block.ReceivedAt = task.time
+							block.AnnouncedAt = &task.announcedTime
 							blocks = append(blocks, block)
 						} else {
 							f.forgetHash(hash)
@@ -923,6 +932,31 @@ func (f *BlockFetcher) importBlocks(peer string, block *types.Block) {
 			log.Debug("Propagated block import failed", "peer", peer, "number", block.Number(), "hash", hash, "err", err)
 			return
 		}
+
+		if f.enableBlockTracking {
+			// Log the insertion event
+			var (
+				msg         string
+				delayInMs   uint64
+				prettyDelay common.PrettyDuration
+			)
+
+			if block.AnnouncedAt != nil {
+				msg = "[block tracker] Inserted new block with announcement"
+				delayInMs = uint64(time.Since(*block.AnnouncedAt).Milliseconds())
+				prettyDelay = common.PrettyDuration(time.Since(*block.AnnouncedAt))
+			} else {
+				msg = "[block tracker] Inserted new block without announcement"
+				delayInMs = uint64(time.Since(block.ReceivedAt).Milliseconds())
+				prettyDelay = common.PrettyDuration(time.Since(block.ReceivedAt))
+			}
+
+			totalDelayInMs := uint64(time.Now().UnixMilli()) - block.Time()*1000
+			totalDelay := common.PrettyDuration(time.Millisecond * time.Duration(totalDelayInMs))
+
+			log.Info(msg, "number", block.Number().Uint64(), "hash", hash, "delay", prettyDelay, "delayInMs", delayInMs, "totalDelay", totalDelay, "totalDelayInMs", totalDelayInMs)
+		}
+
 		// If import succeeded, broadcast the block
 		blockAnnounceOutTimer.UpdateSince(block.ReceivedAt)
 

eth/fetcher/block_fetcher_test.go

@@ -104,7 +104,7 @@ func newTester(light bool) *fetcherTester {
 		blocks:  map[common.Hash]*types.Block{genesis.Hash(): genesis},
 		drops:   make(map[string]bool),
 	}
-	tester.fetcher = NewBlockFetcher(light, tester.getHeader, tester.getBlock, tester.verifyHeader, tester.broadcastBlock, tester.chainHeight, tester.insertHeaders, tester.insertChain, tester.dropPeer)
+	tester.fetcher = NewBlockFetcher(light, tester.getHeader, tester.getBlock, tester.verifyHeader, tester.broadcastBlock, tester.chainHeight, tester.insertHeaders, tester.insertChain, tester.dropPeer, false)
 	tester.fetcher.Start()
 
 	return tester

eth/handler.go

@@ -97,6 +97,7 @@ type handlerConfig struct {
 	checker             ethereum.ChainValidator
 	RequiredBlocks      map[uint64]common.Hash // Hard coded map of required block hashes for sync challenges
 	EthAPI              *ethapi.BlockChainAPI  // EthAPI to interact
+	enableBlockTracking bool                   // Whether to log information collected while tracking block lifecycle
 }
 
 type handler struct {
@@ -126,6 +127,8 @@ type handler struct {
 
 	requiredBlocks map[uint64]common.Hash
 
+	enableBlockTracking bool
+
 	// channels for fetcher, syncer, txsyncLoop
 	quitSync chan struct{}
 
@@ -154,6 +157,7 @@ func newHandler(config *handlerConfig) (*handler, error) {
 		merger:              config.Merger,
 		ethAPI:              config.EthAPI,
 		requiredBlocks:      config.RequiredBlocks,
+		enableBlockTracking: config.enableBlockTracking,
 		quitSync:            make(chan struct{}),
 		handlerDoneCh:       make(chan struct{}),
 		handlerStartCh:      make(chan struct{}),
@@ -295,7 +299,7 @@ func newHandler(config *handlerConfig) (*handler, error) {
 
 		return n, err
 	}
-	h.blockFetcher = fetcher.NewBlockFetcher(false, nil, h.chain.GetBlockByHash, validator, h.BroadcastBlock, heighter, nil, inserter, h.removePeer)
+	h.blockFetcher = fetcher.NewBlockFetcher(false, nil, h.chain.GetBlockByHash, validator, h.BroadcastBlock, heighter, nil, inserter, h.removePeer, h.enableBlockTracking)
 
 	fetchTx := func(peer string, hashes []common.Hash) error {
 		p := h.peers.peer(peer)
@@ -688,6 +692,11 @@ func (h *handler) minedBroadcastLoop() {
 
 	for obj := range h.minedBlockSub.Chan() {
 		if ev, ok := obj.Data.(core.NewMinedBlockEvent); ok {
+			if h.enableBlockTracking {
+				delayInMs := uint64(time.Now().UnixMilli()) - ev.Block.Time()*1000
+				delay := common.PrettyDuration(time.Millisecond * time.Duration(delayInMs))
+				log.Info("[block tracker] Broadcasting mined block", "number", ev.Block.NumberU64(), "hash", ev.Block.Hash(), "blockTime", ev.Block.Time(), "now", time.Now().Unix(), "delay", delay, "delayInMs", delayInMs)
+			}
 			h.BroadcastBlock(ev.Block, true)  // First propagate block to peers
 			h.BroadcastBlock(ev.Block, false) // Only then announce to the rest
 		}

eth/protocols/eth/handlers.go

@@ -382,8 +382,10 @@ func handleNewBlock(backend Backend, msg Decoder, peer *Peer) error {
 		return nil // TODO(karalabe): return error eventually, but wait a few releases
 	}
 
+	msgTime := msg.Time()
 	ann.Block.ReceivedAt = msg.Time()
 	ann.Block.ReceivedFrom = peer
+	ann.Block.AnnouncedAt = &msgTime
 
 	// Mark the peer as owning the block
 	peer.markBlock(ann.Block.Hash())

internal/cli/server/config.go

@@ -154,6 +154,9 @@ type LoggingConfig struct {
 	// Prepends log messages with call-site location (file and line number)
 	Debug bool `hcl:"debug,optional" toml:"debug,optional"`
 
+	// EnableBlockTracking allows logging of information collected while tracking block lifecycle
+	EnableBlockTracking bool `hcl:"enable-block-tracking,optional" toml:"enable-block-tracking,optional"`
+
 	// TODO - implement this
 	// // Write execution trace to the given file
 	// Trace string `hcl:"trace,optional" toml:"trace,optional"`
@@ -610,6 +613,7 @@ func DefaultConfig() *Config {
 			Json:                false,
 			Backtrace:           "",
 			Debug:               false,
+			EnableBlockTracking: false,
 		},
 		RPCBatchLimit:      100,
 		RPCReturnDataLimit: 100000,
@@ -1186,6 +1190,8 @@ func (c *Config) buildEth(stack *node.Node, accountManager *accounts.Manager) (*
 		n.DatabaseFreezer = c.Ancient
 	}
 
+	n.EnableBlockTracking = c.Logging.EnableBlockTracking
+
 	return &n, nil
 }
 

internal/cli/server/flags.go

@@ -146,6 +146,13 @@ func (c *Command) Flags(config *Config) *flagset.Flagset {
 		Default: c.cliConfig.Logging.Debug,
 		Group:   "Logging",
 	})
+	f.BoolFlag(&flagset.BoolFlag{
+		Name:    "log.enable-block-tracking",
+		Usage:   "Enables additional logging of information collected while tracking block lifecycle",
+		Value:   &c.cliConfig.Logging.EnableBlockTracking,
+		Default: c.cliConfig.Logging.EnableBlockTracking,
+		Group:   "Logging",
+	})
 
 	// heimdall
 	f.StringFlag(&flagset.StringFlag{

packaging/templates/mainnet-v1/archive/config.toml

@@ -21,6 +21,7 @@ gcmode = "archive"
     # json = false
     # backtrace = ""
     # debug = true
+    # enable-block-tracking = false
 
 [p2p]
     maxpeers = 50

packaging/templates/mainnet-v1/sentry/sentry/bor/config.toml

@@ -21,6 +21,7 @@ syncmode = "full"
     # json = false
     # backtrace = ""
     # debug = true
+    # enable-block-tracking = false
 
 [p2p]
     maxpeers = 50

packaging/templates/mainnet-v1/sentry/validator/bor/config.toml

@@ -23,6 +23,7 @@ syncmode = "full"
     # json = false
     # backtrace = ""
     # debug = true
+    # enable-block-tracking = false
 
 [p2p]
     maxpeers = 20

packaging/templates/mainnet-v1/without-sentry/bor/config.toml

@@ -23,6 +23,7 @@ syncmode = "full"
     # json = false
     # backtrace = ""
     # debug = true
+    # enable-block-tracking = false
 
 [p2p]
     maxpeers = 50

packaging/templates/testnet-v4/archive/config.toml

@@ -21,6 +21,7 @@ gcmode = "archive"
     # json = false
     # backtrace = ""
     # debug = true
+    # enable-block-tracking = false
 
 [p2p]
     maxpeers = 50

packaging/templates/testnet-v4/sentry/sentry/bor/config.toml

@@ -21,6 +21,7 @@ syncmode = "full"
     # json = false
     # backtrace = ""
     # debug = true
+    # enable-block-tracking = false
 
 [p2p]
     maxpeers = 50

packaging/templates/testnet-v4/sentry/validator/bor/config.toml

@@ -23,6 +23,7 @@ syncmode = "full"
     # json = false
     # backtrace = ""
     # debug = true
+    # enable-block-tracking = false
 
 [p2p]
     maxpeers = 1

packaging/templates/testnet-v4/without-sentry/bor/config.toml

@@ -23,6 +23,7 @@ syncmode = "full"
     # json = false
     # backtrace = ""
     # debug = true
+    # enable-block-tracking = false
 
 [p2p]
     maxpeers = 50