Merge pull request #3711 from karalabe/update-downloader-logs

eth/downloader: port over old logs from glog to log15

accounts/abi/bind/util.go

@@ -39,7 +39,7 @@ func WaitMined(ctx context.Context, b DeployBackend, tx *types.Transaction) (*ty
 			return receipt, nil
 		}
 		if err != nil {
-			logger.Trace("Receipt retrieval failed", "error", err)
+			logger.Trace("Receipt retrieval failed", "err", err)
 		} else {
 			logger.Trace("Transaction not yet mined")
 		}

accounts/keystore/account_cache.go

@@ -210,7 +210,7 @@ func (ac *accountCache) close() {
 func (ac *accountCache) reload() {
 	accounts, err := ac.scan()
 	if err != nil {
-		log.Debug("Failed to reload keystore contents", "error", err)
+		log.Debug("Failed to reload keystore contents", "err", err)
 	}
 	ac.all = accounts
 	sort.Sort(ac.all)
@@ -250,7 +250,7 @@ func (ac *accountCache) scan() ([]accounts.Account, error) {
 
 		fd, err := os.Open(path)
 		if err != nil {
-			logger.Trace("Failed to open keystore file", "error", err)
+			logger.Trace("Failed to open keystore file", "err", err)
 			continue
 		}
 		buf.Reset(fd)
@@ -260,7 +260,7 @@ func (ac *accountCache) scan() ([]accounts.Account, error) {
 		addr := common.HexToAddress(keyJSON.Address)
 		switch {
 		case err != nil:
-			logger.Debug("Failed to decode keystore key", "error", err)
+			logger.Debug("Failed to decode keystore key", "err", err)
 		case (addr == common.Address{}):
 			logger.Debug("Failed to decode keystore key", "error", "missing or zero address")
 		default:

accounts/keystore/watch.go

@@ -66,7 +66,7 @@ func (w *watcher) loop() {
 	logger := log.New("path", w.ac.keydir)
 
 	if err := notify.Watch(w.ac.keydir, w.ev, notify.All); err != nil {
-		logger.Trace("Failed to watch keystore folder", "error", err)
+		logger.Trace("Failed to watch keystore folder", "err", err)
 		return
 	}
 	defer notify.Stop(w.ev)

accounts/usbwallet/ledger_wallet.go

@@ -262,7 +262,7 @@ func (w *ledgerWallet) heartbeat() {
 	}
 	// In case of error, wait for termination
 	if err != nil {
-		w.logger.Debug("Ledger health-check failed", "error", err)
+		w.logger.Debug("Ledger health-check failed", "err", err)
 		errc = <-w.healthQuit
 	}
 	errc <- err
@@ -396,7 +396,7 @@ func (w *ledgerWallet) selfDerive() {
 			// Retrieve the next derived Ethereum account
 			if nextAddr == (common.Address{}) {
 				if nextAddr, err = w.ledgerDerive(nextPath); err != nil {
-					w.logger.Warn("Ledger account derivation failed", "error", err)
+					w.logger.Warn("Ledger account derivation failed", "err", err)
 					break
 				}
 			}
@@ -407,12 +407,12 @@ func (w *ledgerWallet) selfDerive() {
 			)
 			balance, err = w.deriveChain.BalanceAt(context, nextAddr, nil)
 			if err != nil {
-				w.logger.Warn("Ledger balance retrieval failed", "error", err)
+				w.logger.Warn("Ledger balance retrieval failed", "err", err)
 				break
 			}
 			nonce, err = w.deriveChain.NonceAt(context, nextAddr, nil)
 			if err != nil {
-				w.logger.Warn("Ledger nonce retrieval failed", "error", err)
+				w.logger.Warn("Ledger nonce retrieval failed", "err", err)
 				break
 			}
 			// If the next account is empty, stop self-derivation, but add it nonetheless
@@ -471,7 +471,7 @@ func (w *ledgerWallet) selfDerive() {
 	}
 	// In case of error, wait for termination
 	if err != nil {
-		w.logger.Debug("Ledger self-derivation failed", "error", err)
+		w.logger.Debug("Ledger self-derivation failed", "err", err)
 		errc = <-w.deriveQuit
 	}
 	errc <- err

eth/downloader/modes.go

@@ -24,3 +24,17 @@ const (
 	FastSync                  // Quickly download the headers, full sync only at the chain head
 	LightSync                 // Download only the headers and terminate afterwards
 )
+
+// String implements the stringer interface.
+func (mode SyncMode) String() string {
+	switch mode {
+	case FullSync:
+		return "full"
+	case FastSync:
+		return "fast"
+	case LightSync:
+		return "light"
+	default:
+		return "unknown"
+	}
+}

eth/downloader/peer.go

@@ -25,12 +25,12 @@ import (
 	"math"
 	"math/big"
 	"sort"
-	"strings"
 	"sync"
 	"sync/atomic"
 	"time"
 
 	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/log"
 )
 
 const (
@@ -86,7 +86,8 @@ type peer struct {
 	getReceipts receiptFetcherFn // [eth/63] Method to retrieve a batch of block transaction receipts
 	getNodeData stateFetcherFn   // [eth/63] Method to retrieve a batch of state trie data
 
-	version int // Eth protocol version number to switch strategies
+	version int        // Eth protocol version number to switch strategies
+	logger  log.Logger // Contextual logger to add extra infos to peer logs
 	lock    sync.RWMutex
 }
 
@@ -94,7 +95,8 @@ type peer struct {
 // mechanisms.
 func newPeer(id string, version int, currentHead currentHeadRetrievalFn,
 	getRelHeaders relativeHeaderFetcherFn, getAbsHeaders absoluteHeaderFetcherFn, getBlockBodies blockBodyFetcherFn,
-	getReceipts receiptFetcherFn, getNodeData stateFetcherFn) *peer {
+	getReceipts receiptFetcherFn, getNodeData stateFetcherFn, logger log.Logger) *peer {
+
 	return &peer{
 		id:      id,
 		lacking: make(map[common.Hash]struct{}),
@@ -108,6 +110,7 @@ func newPeer(id string, version int, currentHead currentHeadRetrievalFn,
 		getNodeData: getNodeData,
 
 		version: version,
+		logger:  logger,
 	}
 }
 
@@ -268,6 +271,11 @@ func (p *peer) setIdle(started time.Time, delivered int, throughput *float64, id
 
 	*throughput = (1-measurementImpact)*(*throughput) + measurementImpact*measured
 	p.rtt = time.Duration((1-measurementImpact)*float64(p.rtt) + measurementImpact*float64(elapsed))
+
+	p.logger.Trace("Peer throughput measurements updated",
+		"hps", p.headerThroughput, "bps", p.blockThroughput,
+		"rps", p.receiptThroughput, "sps", p.stateThroughput,
+		"miss", len(p.lacking), "rtt", p.rtt)
 }
 
 // HeaderCapacity retrieves the peers header download allowance based on its
@@ -332,21 +340,6 @@ func (p *peer) Lacks(hash common.Hash) bool {
 	return ok
 }
 
-// String implements fmt.Stringer.
-func (p *peer) String() string {
-	p.lock.RLock()
-	defer p.lock.RUnlock()
-
-	return fmt.Sprintf("Peer %s [%s]", p.id, strings.Join([]string{
-		fmt.Sprintf("hs %3.2f/s", p.headerThroughput),
-		fmt.Sprintf("bs %3.2f/s", p.blockThroughput),
-		fmt.Sprintf("rs %3.2f/s", p.receiptThroughput),
-		fmt.Sprintf("ss %3.2f/s", p.stateThroughput),
-		fmt.Sprintf("miss %4d", len(p.lacking)),
-		fmt.Sprintf("rtt %v", p.rtt),
-	}, ", "))
-}
-
 // peerSet represents the collection of active peer participating in the chain
 // download procedure.
 type peerSet struct {

eth/downloader/queue.go

@@ -364,20 +364,20 @@ func (q *queue) Schedule(headers []*types.Header, from uint64) []*types.Header {
 		// Make sure chain order is honoured and preserved throughout
 		hash := header.Hash()
 		if header.Number == nil || header.Number.Uint64() != from {
-			log.Warn(fmt.Sprintf("Header #%v [%x…] broke chain ordering, expected %d", header.Number, hash[:4], from))
+			log.Warn("Header broke chain ordering", "number", header.Number, "hash", hash.Hex()[2:10], "expected", from)
 			break
 		}
 		if q.headerHead != (common.Hash{}) && q.headerHead != header.ParentHash {
-			log.Warn(fmt.Sprintf("Header #%v [%x…] broke chain ancestry", header.Number, hash[:4]))
+			log.Warn("Header broke chain ancestry", "number", header.Number, "hash", hash.Hex()[2:10])
 			break
 		}
 		// Make sure no duplicate requests are executed
 		if _, ok := q.blockTaskPool[hash]; ok {
-			log.Warn(fmt.Sprintf("Header #%d [%x…] already scheduled for block fetch", header.Number.Uint64(), hash[:4]))
+			log.Warn("Header  already scheduled for block fetch", "number", header.Number, "hash", hash.Hex()[2:10])
 			continue
 		}
 		if _, ok := q.receiptTaskPool[hash]; ok {
-			log.Warn(fmt.Sprintf("Header #%d [%x…] already scheduled for receipt fetch", header.Number.Uint64(), hash[:4]))
+			log.Warn("Header already scheduled for receipt fetch", "number", header.Number, "hash", hash.Hex()[2:10])
 			continue
 		}
 		// Queue the header for content retrieval
@@ -391,7 +391,7 @@ func (q *queue) Schedule(headers []*types.Header, from uint64) []*types.Header {
 		}
 		if q.mode == FastSync && header.Number.Uint64() == q.fastSyncPivot {
 			// Pivoting point of the fast sync, switch the state retrieval to this
-			log.Debug(fmt.Sprintf("Switching state downloads to %d [%x…]", header.Number.Uint64(), header.Hash().Bytes()[:4]))
+			log.Debug("Switching state downloads to new block", "number", header.Number, "hash", hash.Hex()[2:10])
 
 			q.stateTaskIndex = 0
 			q.stateTaskPool = make(map[common.Hash]int)
@@ -872,10 +872,10 @@ func (q *queue) DeliverHeaders(id string, headers []*types.Header, headerProcCh
 	accepted := len(headers) == MaxHeaderFetch
 	if accepted {
 		if headers[0].Number.Uint64() != request.From {
-			log.Trace(fmt.Sprintf("Peer %s: first header #%v [%x…] broke chain ordering, expected %d", id, headers[0].Number, headers[0].Hash().Bytes()[:4], request.From))
+			log.Trace("First header broke chain ordering", "peer", id, "number", headers[0].Number, "hash", headers[0].Hash().Hex()[2:10], request.From)
 			accepted = false
 		} else if headers[len(headers)-1].Hash() != target {
-			log.Trace(fmt.Sprintf("Peer %s: last header #%v [%x…] broke skeleton structure, expected %x", id, headers[len(headers)-1].Number, headers[len(headers)-1].Hash().Bytes()[:4], target[:4]))
+			log.Trace("Last header broke skeleton structure ", "peer", id, "number", headers[len(headers)-1].Number, "hash", headers[len(headers)-1].Hash().Hex()[2:10], "expected", target.Hex()[2:10])
 			accepted = false
 		}
 	}
@@ -883,12 +883,12 @@ func (q *queue) DeliverHeaders(id string, headers []*types.Header, headerProcCh
 		for i, header := range headers[1:] {
 			hash := header.Hash()
 			if want := request.From + 1 + uint64(i); header.Number.Uint64() != want {
-				log.Warn(fmt.Sprintf("Peer %s: header #%v [%x…] broke chain ordering, expected %d", id, header.Number, hash[:4], want))
+				log.Warn("Header broke chain ordering", "peer", id, "number", header.Number, "hash", hash.Hex()[2:10], "expected", want)
 				accepted = false
 				break
 			}
 			if headers[i].Hash() != header.ParentHash {
-				log.Warn(fmt.Sprintf("Peer %s: header #%v [%x…] broke chain ancestry", id, header.Number, hash[:4]))
+				log.Warn("Header broke chain ancestry", "peer", id, "number", header.Number, "hash", hash.Hex()[2:10])
 				accepted = false
 				break
 			}
@@ -896,7 +896,7 @@ func (q *queue) DeliverHeaders(id string, headers []*types.Header, headerProcCh
 	}
 	// If the batch of headers wasn't accepted, mark as unavailable
 	if !accepted {
-		log.Trace(fmt.Sprintf("Peer %s: skeleton filling from header #%d not accepted", id, request.From))
+		log.Trace("Skeleton filling not accepted", "peer", id, "from", request.From)
 
 		miss := q.headerPeerMiss[id]
 		if miss == nil {
@@ -923,7 +923,7 @@ func (q *queue) DeliverHeaders(id string, headers []*types.Header, headerProcCh
 
 		select {
 		case headerProcCh <- process:
-			log.Trace(fmt.Sprintf("%s: pre-scheduled %d headers from #%v", id, len(process), process[0].Number))
+			log.Trace("Pre-scheduled new headers", "peer", id, "count", len(process), "from", process[0].Number)
 			q.headerProced += len(process)
 		default:
 		}