all: next batch of log polishes to contextual versions

This commit is contained in:
Péter Szilágyi
2017-02-28 13:35:17 +02:00
parent d4f60d362b
commit e588e0ca2b
18 changed files with 203 additions and 242 deletions

View File

@ -160,9 +160,9 @@ func NewBlockChain(chainDb ethdb.Database, config *params.ChainConfig, pow pow.P
headerByNumber := bc.GetHeaderByNumber(header.Number.Uint64())
// make sure the headerByNumber (if present) is in our current canonical chain
if headerByNumber != nil && headerByNumber.Hash() == header.Hash() {
log.Error(fmt.Sprintf("Found bad hash, rewinding chain to block #%d [%x…]", header.Number, header.ParentHash[:4]))
log.Error("Found bad hash, rewinding chain", "number", header.Number, "hash", header.ParentHash)
bc.SetHead(header.Number.Uint64() - 1)
log.Error(fmt.Sprint("Chain rewind was successful, resuming normal operation"))
log.Error("Chain rewind was successful, resuming normal operation")
}
}
}
@ -219,9 +219,9 @@ func (self *BlockChain) loadLastState() error {
blockTd := self.GetTd(self.currentBlock.Hash(), self.currentBlock.NumberU64())
fastTd := self.GetTd(self.currentFastBlock.Hash(), self.currentFastBlock.NumberU64())
log.Info(fmt.Sprintf("Last header: #%d [%x…] TD=%v", currentHeader.Number, currentHeader.Hash().Bytes()[:4], headerTd))
log.Info(fmt.Sprintf("Last block: #%d [%x…] TD=%v", self.currentBlock.Number(), self.currentBlock.Hash().Bytes()[:4], blockTd))
log.Info(fmt.Sprintf("Fast block: #%d [%x…] TD=%v", self.currentFastBlock.Number(), self.currentFastBlock.Hash().Bytes()[:4], fastTd))
log.Info("Loaded most recent local header", "number", currentHeader.Number, "hash", currentHeader.Hash(), "td", headerTd)
log.Info("Loaded most recent local full block", "number", self.currentBlock.Number(), "hash", self.currentBlock.Hash(), "td", blockTd)
log.Info("Loaded most recent local fast block", "number", self.currentFastBlock.Number(), "hash", self.currentFastBlock.Hash(), "td", fastTd)
return nil
}
@ -262,10 +262,10 @@ func (bc *BlockChain) SetHead(head uint64) {
}
if err := WriteHeadBlockHash(bc.chainDb, bc.currentBlock.Hash()); err != nil {
log.Crit(fmt.Sprintf("failed to reset head block hash: %v", err))
log.Crit("Failed to reset head full block", "err", err)
}
if err := WriteHeadFastBlockHash(bc.chainDb, bc.currentFastBlock.Hash()); err != nil {
log.Crit(fmt.Sprintf("failed to reset head fast block hash: %v", err))
log.Crit("Failed to reset head fast block", "err", err)
}
bc.loadLastState()
}
@ -286,7 +286,7 @@ func (self *BlockChain) FastSyncCommitHead(hash common.Hash) error {
self.currentBlock = block
self.mu.Unlock()
log.Info(fmt.Sprintf("committed block #%d [%x…] as new head", block.Number(), hash[:4]))
log.Info("Committed new head block", "number", block.Number(), "hash", hash)
return nil
}
@ -390,10 +390,10 @@ func (bc *BlockChain) ResetWithGenesisBlock(genesis *types.Block) {
// Prepare the genesis block and reinitialise the chain
if err := bc.hc.WriteTd(genesis.Hash(), genesis.NumberU64(), genesis.Difficulty()); err != nil {
log.Crit(fmt.Sprintf("failed to write genesis block TD: %v", err))
log.Crit("Failed to write genesis block TD", "err", err)
}
if err := WriteBlock(bc.chainDb, genesis); err != nil {
log.Crit(fmt.Sprintf("failed to write genesis block: %v", err))
log.Crit("Failed to write genesis block", "err", err)
}
bc.genesisBlock = genesis
bc.insert(bc.genesisBlock)
@ -416,8 +416,7 @@ func (self *BlockChain) ExportN(w io.Writer, first uint64, last uint64) error {
if first > last {
return fmt.Errorf("export failed: first (%d) is greater than last (%d)", first, last)
}
log.Info(fmt.Sprintf("exporting %d blocks...\n", last-first+1))
log.Info("Exporting batch of blocks", "count", last-first+1)
for nr := first; nr <= last; nr++ {
block := self.GetBlockByNumber(nr)
@ -445,10 +444,10 @@ func (bc *BlockChain) insert(block *types.Block) {
// Add the block to the canonical chain number scheme and mark as the head
if err := WriteCanonicalHash(bc.chainDb, block.Hash(), block.NumberU64()); err != nil {
log.Crit(fmt.Sprintf("failed to insert block number: %v", err))
log.Crit("Failed to insert block number", "err", err)
}
if err := WriteHeadBlockHash(bc.chainDb, block.Hash()); err != nil {
log.Crit(fmt.Sprintf("failed to insert head block hash: %v", err))
log.Crit("Failed to insert head block hash", "err", err)
}
bc.currentBlock = block
@ -457,7 +456,7 @@ func (bc *BlockChain) insert(block *types.Block) {
bc.hc.SetCurrentHeader(block.Header())
if err := WriteHeadFastBlockHash(bc.chainDb, block.Hash()); err != nil {
log.Crit(fmt.Sprintf("failed to insert head fast block hash: %v", err))
log.Crit("Failed to insert head fast block hash", "err", err)
}
bc.currentFastBlock = block
}
@ -588,8 +587,7 @@ func (bc *BlockChain) Stop() {
atomic.StoreInt32(&bc.procInterrupt, 1)
bc.wg.Wait()
log.Info(fmt.Sprint("Chain manager stopped"))
log.Info("Blockchain manager stopped")
}
func (self *BlockChain) procFutureBlocks() {
@ -683,11 +681,11 @@ func (self *BlockChain) InsertReceiptChain(blockChain types.Blocks, receiptChain
for i := 1; i < len(blockChain); i++ {
if blockChain[i].NumberU64() != blockChain[i-1].NumberU64()+1 || blockChain[i].ParentHash() != blockChain[i-1].Hash() {
// Chain broke ancestry, log a messge (programming error) and skip insertion
failure := fmt.Errorf("non contiguous insert: item %d is #%d [%x…], item %d is #%d [%x…] (parent [%x…])", i-1, blockChain[i-1].NumberU64(),
blockChain[i-1].Hash().Bytes()[:4], i, blockChain[i].NumberU64(), blockChain[i].Hash().Bytes()[:4], blockChain[i].ParentHash().Bytes()[:4])
log.Error("Non contiguous receipt insert", "number", blockChain[i].Number(), "hash", blockChain[i].Hash(), "parent", blockChain[i].ParentHash(),
"prevnumber", blockChain[i-1].Number(), "prevhash", blockChain[i-1].Hash())
log.Error(fmt.Sprint(failure.Error()))
return 0, failure
return 0, fmt.Errorf("non contiguous insert: item %d is #%d [%x…], item %d is #%d [%x…] (parent [%x…])", i-1, blockChain[i-1].NumberU64(),
blockChain[i-1].Hash().Bytes()[:4], i, blockChain[i].NumberU64(), blockChain[i].Hash().Bytes()[:4], blockChain[i].ParentHash().Bytes()[:4])
}
}
// Pre-checks passed, start the block body and receipt imports
@ -734,31 +732,31 @@ func (self *BlockChain) InsertReceiptChain(blockChain types.Blocks, receiptChain
if err := WriteBody(self.chainDb, block.Hash(), block.NumberU64(), block.Body()); err != nil {
errs[index] = fmt.Errorf("failed to write block body: %v", err)
atomic.AddInt32(&failed, 1)
log.Crit(fmt.Sprint(errs[index]))
log.Crit("Failed to write block body", "err", err)
return
}
if err := WriteBlockReceipts(self.chainDb, block.Hash(), block.NumberU64(), receipts); err != nil {
errs[index] = fmt.Errorf("failed to write block receipts: %v", err)
atomic.AddInt32(&failed, 1)
log.Crit(fmt.Sprint(errs[index]))
log.Crit("Failed to write block receipts", "err", err)
return
}
if err := WriteMipmapBloom(self.chainDb, block.NumberU64(), receipts); err != nil {
errs[index] = fmt.Errorf("failed to write log blooms: %v", err)
atomic.AddInt32(&failed, 1)
log.Crit(fmt.Sprint(errs[index]))
log.Crit("Failed to write log blooms", "err", err)
return
}
if err := WriteTransactions(self.chainDb, block); err != nil {
errs[index] = fmt.Errorf("failed to write individual transactions: %v", err)
atomic.AddInt32(&failed, 1)
log.Crit(fmt.Sprint(errs[index]))
log.Crit("Failed to write individual transactions", "err", err)
return
}
if err := WriteReceipts(self.chainDb, receipts); err != nil {
errs[index] = fmt.Errorf("failed to write individual receipts: %v", err)
atomic.AddInt32(&failed, 1)
log.Crit(fmt.Sprint(errs[index]))
log.Crit("Failed to write individual receipts", "err", err)
return
}
atomic.AddInt32(&stats.processed, 1)
@ -784,7 +782,7 @@ func (self *BlockChain) InsertReceiptChain(blockChain types.Blocks, receiptChain
}
}
if atomic.LoadInt32(&self.procInterrupt) == 1 {
log.Debug(fmt.Sprint("premature abort during receipt chain processing"))
log.Debug("Premature abort during receipts processing")
return 0, nil
}
// Update the head fast sync block if better
@ -792,20 +790,16 @@ func (self *BlockChain) InsertReceiptChain(blockChain types.Blocks, receiptChain
head := blockChain[len(errs)-1]
if self.GetTd(self.currentFastBlock.Hash(), self.currentFastBlock.NumberU64()).Cmp(self.GetTd(head.Hash(), head.NumberU64())) < 0 {
if err := WriteHeadFastBlockHash(self.chainDb, head.Hash()); err != nil {
log.Crit(fmt.Sprintf("failed to update head fast block hash: %v", err))
log.Crit("Failed to update head fast block hash", "err", err)
}
self.currentFastBlock = head
}
self.mu.Unlock()
// Report some public statistics so the user has a clue what's going on
first, last := blockChain[0], blockChain[len(blockChain)-1]
ignored := ""
if stats.ignored > 0 {
ignored = fmt.Sprintf(" (%d ignored)", stats.ignored)
}
log.Info(fmt.Sprintf("imported %4d receipts in %9v. #%d [%x… / %x…]%s", stats.processed, common.PrettyDuration(time.Since(start)), last.Number(), first.Hash().Bytes()[:4], last.Hash().Bytes()[:4], ignored))
last := blockChain[len(blockChain)-1]
log.Info("Imported new block receipts", "count", stats.processed, "number", last.Number(), "hash", last.Hash(),
"elapsed", common.PrettyDuration(time.Since(start)), "ignored", stats.ignored)
return 0, nil
}
@ -829,10 +823,10 @@ func (self *BlockChain) WriteBlock(block *types.Block) (status WriteStatus, err
// Irrelevant of the canonical status, write the block itself to the database
if err := self.hc.WriteTd(block.Hash(), block.NumberU64(), externTd); err != nil {
log.Crit(fmt.Sprintf("failed to write block total difficulty: %v", err))
log.Crit("Failed to write block total difficulty", "err", err)
}
if err := WriteBlock(self.chainDb, block); err != nil {
log.Crit(fmt.Sprintf("failed to write block contents: %v", err))
log.Crit("Failed to write block contents", "err", err)
}
// If the total difficulty is higher than our known, add it to the canonical chain
@ -863,11 +857,11 @@ func (self *BlockChain) InsertChain(chain types.Blocks) (int, error) {
for i := 1; i < len(chain); i++ {
if chain[i].NumberU64() != chain[i-1].NumberU64()+1 || chain[i].ParentHash() != chain[i-1].Hash() {
// Chain broke ancestry, log a messge (programming error) and skip insertion
failure := fmt.Errorf("non contiguous insert: item %d is #%d [%x…], item %d is #%d [%x…] (parent [%x…])",
i-1, chain[i-1].NumberU64(), chain[i-1].Hash().Bytes()[:4], i, chain[i].NumberU64(), chain[i].Hash().Bytes()[:4], chain[i].ParentHash().Bytes()[:4])
log.Error("Non contiguous block insert", "number", chain[i].Number(), "hash", chain[i].Hash(),
"parent", chain[i].ParentHash(), "prevnumber", chain[i-1].Number(), "prevhash", chain[i-1].Hash())
log.Error(fmt.Sprint(failure.Error()))
return 0, failure
return 0, fmt.Errorf("non contiguous insert: item %d is #%d [%x…], item %d is #%d [%x…] (parent [%x…])", i-1, chain[i-1].NumberU64(),
chain[i-1].Hash().Bytes()[:4], i, chain[i].NumberU64(), chain[i].Hash().Bytes()[:4], chain[i].ParentHash().Bytes()[:4])
}
}
// Pre-checks passed, start the full block imports
@ -893,7 +887,7 @@ func (self *BlockChain) InsertChain(chain types.Blocks) (int, error) {
for i, block := range chain {
if atomic.LoadInt32(&self.procInterrupt) == 1 {
log.Debug(fmt.Sprint("Premature abort during block chain processing"))
log.Debug("Premature abort during blocks processing")
break
}
bstart := time.Now()
@ -903,8 +897,8 @@ func (self *BlockChain) InsertChain(chain types.Blocks) (int, error) {
r := <-nonceResults
nonceChecked[r.index] = true
if !r.valid {
block := chain[r.index]
return r.index, &BlockNonceErr{Hash: block.Hash(), Number: block.Number(), Nonce: block.Nonce()}
invalid := chain[r.index]
return r.index, &BlockNonceErr{Hash: invalid.Hash(), Number: invalid.Number(), Nonce: invalid.Nonce()}
}
}
@ -978,7 +972,7 @@ func (self *BlockChain) InsertChain(chain types.Blocks) (int, error) {
// coalesce logs for later processing
coalescedLogs = append(coalescedLogs, logs...)
if err := WriteBlockReceipts(self.chainDb, block.Hash(), block.NumberU64(), receipts); err != nil {
if err = WriteBlockReceipts(self.chainDb, block.Hash(), block.NumberU64(), receipts); err != nil {
return i, err
}
@ -990,9 +984,9 @@ func (self *BlockChain) InsertChain(chain types.Blocks) (int, error) {
switch status {
case CanonStatTy:
log.Debug("", "msg", log.Lazy{Fn: func() string {
return fmt.Sprintf("inserted block #%d [%x…] in %9v: %3d txs %7v gas %d uncles.", block.Number(), block.Hash().Bytes()[0:4], common.PrettyDuration(time.Since(bstart)), len(block.Transactions()), block.GasUsed(), len(block.Uncles()))
}})
log.Debug("Inserted new block", "number", block.Number(), "hash", block.Hash(), "uncles", len(block.Uncles()),
"txs", len(block.Transactions()), "gas", block.GasUsed(), "elapsed", common.PrettyDuration(time.Since(bstart)))
blockInsertTimer.UpdateSince(bstart)
events = append(events, ChainEvent{block, block.Hash(), logs})
@ -1013,9 +1007,9 @@ func (self *BlockChain) InsertChain(chain types.Blocks) (int, error) {
return i, err
}
case SideStatTy:
log.Trace("", "msg", log.Lazy{Fn: func() string {
return fmt.Sprintf("inserted forked block #%d [%x…] (TD=%v) in %9v: %3d txs %d uncles.", block.Number(), block.Hash().Bytes()[0:4], block.Difficulty(), common.PrettyDuration(time.Since(bstart)), len(block.Transactions()), len(block.Uncles()))
}})
log.Debug("Inserted forked block", "number", block.Number(), "hash", block.Hash(), "diff", block.Difficulty(), "elapsed",
common.PrettyDuration(time.Since(bstart)), "txs", len(block.Transactions()), "gas", block.GasUsed(), "uncles", len(block.Uncles()))
blockInsertTimer.UpdateSince(bstart)
events = append(events, ChainSideEvent{block})
@ -1055,19 +1049,22 @@ func (st *insertStats) report(chain []*types.Block, index int) {
)
// If we're at the last block of the batch or report period reached, log
if index == len(chain)-1 || elapsed >= statsReportLimit {
start, end := chain[st.lastIndex], chain[index]
txcount := countTransactions(chain[st.lastIndex : index+1])
var hashes, extra string
if st.queued > 0 || st.ignored > 0 {
extra = fmt.Sprintf(" (%d queued %d ignored)", st.queued, st.ignored)
var (
end = chain[index]
txs = countTransactions(chain[st.lastIndex : index+1])
)
context := []interface{}{
"blocks", st.processed, "number", end.Number(), "hash", end.Hash(), "txs", txs,
"mgas", float64(st.usedGas) / 1000000, "elapsed", common.PrettyDuration(elapsed),
"mgasps", float64(st.usedGas) * 1000 / float64(elapsed),
}
if st.processed > 1 {
hashes = fmt.Sprintf("%x… / %x…", start.Hash().Bytes()[:4], end.Hash().Bytes()[:4])
} else {
hashes = fmt.Sprintf("%x…", end.Hash().Bytes()[:4])
if st.queued > 0 {
context = append(context, []interface{}{"queued", st.queued}...)
}
log.Info(fmt.Sprintf("imported %4d blocks, %5d txs (%7.3f Mg) in %9v (%6.3f Mg/s). #%v [%s]%s", st.processed, txcount, float64(st.usedGas)/1000000, common.PrettyDuration(elapsed), float64(st.usedGas)*1000/float64(elapsed), end.Number(), hashes, extra))
if st.ignored > 0 {
context = append(context, []interface{}{"ignored", st.ignored}...)
}
log.Info("Imported new chain segment", context...)
*st = insertStats{startTime: now, lastIndex: index}
}
@ -1152,19 +1149,8 @@ func (self *BlockChain) reorg(oldBlock, newBlock *types.Block) error {
if len(oldChain) > 63 {
logFn = log.Warn
}
logFn("", "msg", log.Lazy{Fn: func() string {
oldLen, newLen := len(oldChain), len(newChain)
newLast, newFirst := newChain[0], newChain[newLen-1]
oldLast, oldFirst := oldChain[0], oldChain[oldLen-1]
return fmt.Sprintf("Chain split detected after #%v [%x…]. Reorganising chain (-%v +%v blocks), rejecting #%v-#%v [%x…/%x…] in favour of #%v-#%v [%x…/%x…]",
commonBlock.Number(), commonBlock.Hash().Bytes()[:4],
oldLen, newLen,
oldFirst.Number(), oldLast.Number(),
oldFirst.Hash().Bytes()[:4], oldLast.Hash().Bytes()[:4],
newFirst.Number(), newLast.Number(),
newFirst.Hash().Bytes()[:4], newLast.Hash().Bytes()[:4])
}})
logFn("Chain split detected", "number", commonBlock.Number(), "hash", commonBlock.Hash(),
"drop", len(oldChain), "dropfrom", oldChain[0].Hash(), "add", len(newChain), "addfrom", newChain[0].Hash())
var addedTxs types.Transactions
// insert blocks. Order does not matter. Last block will be written in ImportChain itself which creates the new head properly
@ -1271,12 +1257,12 @@ func (bc *BlockChain) addBadBlock(block *types.Block) {
// reportBlock logs a bad block error.
func (bc *BlockChain) reportBlock(block *types.Block, receipts types.Receipts, err error) {
bc.addBadBlock(block)
log.Error("", "msg", log.Lazy{Fn: func() string {
var receiptString string
for _, receipt := range receipts {
receiptString += fmt.Sprintf("\t%v\n", receipt)
}
return fmt.Sprintf(`
var receiptString string
for _, receipt := range receipts {
receiptString += fmt.Sprintf("\t%v\n", receipt)
}
log.Error(fmt.Sprintf(`
########## BAD BLOCK #########
Chain config: %v
@ -1286,8 +1272,7 @@ Hash: 0x%x
Error: %v
##############################
`, bc.config, block.Number(), block.Hash(), receiptString, err)
}})
`, bc.config, block.Number(), block.Hash(), receiptString, err))
}
// InsertHeaderChain attempts to insert the given header chain in to the local