Merge pull request #3696 from karalabe/contextual-logger

Contextual logger

5 files changed, 42 insertions, 41 deletions

diff --git a/accounts/abi/bind/util.go b/accounts/abi/bind/util.go
index bbb6d6a75..ca79694ef 100644
--- a/accounts/abi/bind/util.go
+++ b/accounts/abi/bind/util.go
@@ -22,26 +22,26 @@ import (
 
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/core/types"
-	"github.com/ethereum/go-ethereum/logger"
-	"github.com/ethereum/go-ethereum/logger/glog"
+	"github.com/ethereum/go-ethereum/log"
 	"golang.org/x/net/context"
 )
 
 // WaitMined waits for tx to be mined on the blockchain.
 // It stops waiting when the context is canceled.
 func WaitMined(ctx context.Context, b DeployBackend, tx *types.Transaction) (*types.Receipt, error) {
-	queryTicker := time.NewTicker(1 * time.Second)
+	queryTicker := time.NewTicker(time.Second)
 	defer queryTicker.Stop()
-	loghash := tx.Hash().Hex()[:8]
+
+	logger := log.New("hash", tx.Hash().Hex()[:8])
 	for {
 		receipt, err := b.TransactionReceipt(ctx, tx.Hash())
 		if receipt != nil {
 			return receipt, nil
 		}
 		if err != nil {
-			glog.V(logger.Detail).Infof("tx %x error: %v", loghash, err)
+			logger.Trace("Receipt retrieval failed", "error", err)
 		} else {
-			glog.V(logger.Detail).Infof("tx %x not yet mined...", loghash)
+			logger.Trace("Transaction not yet mined")
 		}
 		// Wait for the next round.
 		select {
diff --git a/accounts/keystore/account_cache.go b/accounts/keystore/account_cache.go
index 3fae3ef5b..866f8ae7b 100644
--- a/accounts/keystore/account_cache.go
+++ b/accounts/keystore/account_cache.go
@@ -30,8 +30,7 @@ import (
 
 	"github.com/ethereum/go-ethereum/accounts"
 	"github.com/ethereum/go-ethereum/common"
-	"github.com/ethereum/go-ethereum/logger"
-	"github.com/ethereum/go-ethereum/logger/glog"
+	"github.com/ethereum/go-ethereum/log"
 )
 
 // Minimum amount of time between cache reloads. This limit applies if the platform does
@@ -210,8 +209,8 @@ func (ac *accountCache) close() {
 // Callers must hold ac.mu.
 func (ac *accountCache) reload() {
 	accounts, err := ac.scan()
-	if err != nil && glog.V(logger.Debug) {
-		glog.Errorf("can't load keys: %v", err)
+	if err != nil {
+		log.Debug("Failed to reload keystore contents", "error", err)
 	}
 	ac.all = accounts
 	sort.Sort(ac.all)
@@ -225,7 +224,7 @@ func (ac *accountCache) reload() {
 	case ac.notify <- struct{}{}:
 	default:
 	}
-	glog.V(logger.Debug).Infof("reloaded keys, cache has %d accounts", len(ac.all))
+	log.Debug("Reloaded keystore contents", "accounts", len(ac.all))
 }
 
 func (ac *accountCache) scan() ([]accounts.Account, error) {
@@ -244,12 +243,14 @@ func (ac *accountCache) scan() ([]accounts.Account, error) {
 	for _, fi := range files {
 		path := filepath.Join(ac.keydir, fi.Name())
 		if skipKeyFile(fi) {
-			glog.V(logger.Detail).Infof("ignoring file %s", path)
+			log.Trace("Ignoring file on account scan", "path", path)
 			continue
 		}
+		logger := log.New("path", path)
+
 		fd, err := os.Open(path)
 		if err != nil {
-			glog.V(logger.Detail).Infoln(err)
+			logger.Trace("Failed to open keystore file", "error", err)
 			continue
 		}
 		buf.Reset(fd)
@@ -259,9 +260,9 @@ func (ac *accountCache) scan() ([]accounts.Account, error) {
 		addr := common.HexToAddress(keyJSON.Address)
 		switch {
 		case err != nil:
-			glog.V(logger.Debug).Infof("can't decode key %s: %v", path, err)
+			logger.Debug("Failed to decode keystore key", "error", err)
 		case (addr == common.Address{}):
-			glog.V(logger.Debug).Infof("can't decode key %s: missing or zero address", path)
+			logger.Debug("Failed to decode keystore key", "error", "missing or zero address")
 		default:
 			addrs = append(addrs, accounts.Account{Address: addr, URL: accounts.URL{Scheme: KeyStoreScheme, Path: path}})
 		}
diff --git a/accounts/keystore/watch.go b/accounts/keystore/watch.go
index 0b4401255..ae97805be 100644
--- a/accounts/keystore/watch.go
+++ b/accounts/keystore/watch.go
@@ -21,8 +21,7 @@ package keystore
 import (
 	"time"
 
-	"github.com/ethereum/go-ethereum/logger"
-	"github.com/ethereum/go-ethereum/logger/glog"
+	"github.com/ethereum/go-ethereum/log"
 	"github.com/rjeczalik/notify"
 )
 
@@ -64,15 +63,16 @@ func (w *watcher) loop() {
 		w.starting = false
 		w.ac.mu.Unlock()
 	}()
+	logger := log.New("path", w.ac.keydir)
 
-	err := notify.Watch(w.ac.keydir, w.ev, notify.All)
-	if err != nil {
-		glog.V(logger.Detail).Infof("can't watch %s: %v", w.ac.keydir, err)
+	if err := notify.Watch(w.ac.keydir, w.ev, notify.All); err != nil {
+		logger.Trace("Failed to watch keystore folder", "error", err)
 		return
 	}
 	defer notify.Stop(w.ev)
-	glog.V(logger.Detail).Infof("now watching %s", w.ac.keydir)
-	defer glog.V(logger.Detail).Infof("no longer watching %s", w.ac.keydir)
+
+	logger.Trace("Started watching keystore folder")
+	defer logger.Trace("Stopped watching keystore folder")
 
 	w.ac.mu.Lock()
 	w.running = true
diff --git a/accounts/usbwallet/ledger_hub.go b/accounts/usbwallet/ledger_hub.go
index 70396d314..d1aeed748 100644
--- a/accounts/usbwallet/ledger_hub.go
+++ b/accounts/usbwallet/ledger_hub.go
@@ -27,6 +27,7 @@ import (
 
 	"github.com/ethereum/go-ethereum/accounts"
 	"github.com/ethereum/go-ethereum/event"
+	"github.com/ethereum/go-ethereum/log"
 	"github.com/karalabe/hid"
 )
 
@@ -120,7 +121,7 @@ func (hub *LedgerHub) refreshWallets() {
 		}
 		// If there are no more wallets or the device is before the next, wrap new wallet
 		if len(hub.wallets) == 0 || hub.wallets[0].URL().Cmp(url) > 0 {
-			wallet := &ledgerWallet{url: &url, info: ledger}
+			wallet := &ledgerWallet{url: &url, info: ledger, logger: log.New("url", url)}
 
 			events = append(events, accounts.WalletEvent{Wallet: wallet, Arrive: true})
 			wallets = append(wallets, wallet)
diff --git a/accounts/usbwallet/ledger_wallet.go b/accounts/usbwallet/ledger_wallet.go
index 235086d1e..6086660f9 100644
--- a/accounts/usbwallet/ledger_wallet.go
+++ b/accounts/usbwallet/ledger_wallet.go
@@ -33,9 +33,9 @@ import (
 	ethereum "github.com/ethereum/go-ethereum"
 	"github.com/ethereum/go-ethereum/accounts"
 	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/common/hexutil"
 	"github.com/ethereum/go-ethereum/core/types"
-	"github.com/ethereum/go-ethereum/logger"
-	"github.com/ethereum/go-ethereum/logger/glog"
+	"github.com/ethereum/go-ethereum/log"
 	"github.com/ethereum/go-ethereum/rlp"
 	"github.com/karalabe/hid"
 	"golang.org/x/net/context"
@@ -123,6 +123,8 @@ type ledgerWallet struct {
 	//     must only ever hold a *read* lock to stateLock.
 	commsLock chan struct{} // Mutex (buf=1) for the USB comms without keeping the state locked
 	stateLock sync.RWMutex  // Protects read and write access to the wallet struct fields
+
+	logger log.Logger // Contextual logger to tag the ledger with its id
 }
 
 // URL implements accounts.Wallet, returning the URL of the Ledger device.
@@ -220,8 +222,8 @@ func (w *ledgerWallet) Open(passphrase string) error {
 //  - libusb on Windows doesn't support hotplug, so we can't detect USB unplugs
 //  - communication timeout on the Ledger requires a device power cycle to fix
 func (w *ledgerWallet) heartbeat() {
-	glog.V(logger.Debug).Infof("%s health-check started", w.url.String())
-	defer glog.V(logger.Debug).Infof("%s health-check stopped", w.url.String())
+	w.logger.Debug("Ledger health-check started")
+	defer w.logger.Debug("Ledger health-check stopped")
 
 	// Execute heartbeat checks until termination or error
 	var (
@@ -260,7 +262,7 @@ func (w *ledgerWallet) heartbeat() {
 	}
 	// In case of error, wait for termination
 	if err != nil {
-		glog.V(logger.Debug).Infof("%s health-check failed: %v", w.url.String(), err)
+		w.logger.Debug("Ledger health-check failed", "error", err)
 		errc = <-w.healthQuit
 	}
 	errc <- err
@@ -348,8 +350,8 @@ func (w *ledgerWallet) Accounts() []accounts.Account {
 // selfDerive is an account derivation loop that upon request attempts to find
 // new non-zero accounts.
 func (w *ledgerWallet) selfDerive() {
-	glog.V(logger.Debug).Infof("%s self-derivation started", w.url.String())
-	defer glog.V(logger.Debug).Infof("%s self-derivation stopped", w.url.String())
+	w.logger.Debug("Ledger self-derivation started")
+	defer w.logger.Debug("Ledger self-derivation stopped")
 
 	// Execute self-derivations until termination or error
 	var (
@@ -394,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 {
-					glog.V(logger.Warn).Infof("%s self-derivation failed: %v", w.url.String(), err)
+					w.logger.Warn("Ledger account derivation failed", "error", err)
 					break
 				}
 			}
@@ -405,12 +407,12 @@ func (w *ledgerWallet) selfDerive() {
 			)
 			balance, err = w.deriveChain.BalanceAt(context, nextAddr, nil)
 			if err != nil {
-				glog.V(logger.Warn).Infof("%s self-derivation balance retrieval failed: %v", w.url.String(), err)
+				w.logger.Warn("Ledger balance retrieval failed", "error", err)
 				break
 			}
 			nonce, err = w.deriveChain.NonceAt(context, nextAddr, nil)
 			if err != nil {
-				glog.V(logger.Warn).Infof("%s self-derivation nonce retrieval failed: %v", w.url.String(), err)
+				w.logger.Warn("Ledger nonce retrieval failed", "error", err)
 				break
 			}
 			// If the next account is empty, stop self-derivation, but add it nonetheless
@@ -430,7 +432,7 @@ func (w *ledgerWallet) selfDerive() {
 
 			// Display a log message to the user for new (or previously empty accounts)
 			if _, known := w.paths[nextAddr]; !known || (!empty && nextAddr == w.deriveNextAddr) {
-				glog.V(logger.Info).Infof("%s discovered %s (balance %22v, nonce %4d) at %s", w.url.String(), nextAddr.Hex(), balance, nonce, path)
+				w.logger.Info("Ledger discovered new account", "address", nextAddr.Hex(), "path", path, "balance", balance, "nonce", nonce)
 			}
 			// Fetch the next potential account
 			if !empty {
@@ -469,7 +471,7 @@ func (w *ledgerWallet) selfDerive() {
 	}
 	// In case of error, wait for termination
 	if err != nil {
-		glog.V(logger.Debug).Infof("%s self-derivation failed: %s", w.url.String(), err)
+		w.logger.Debug("Ledger self-derivation failed", "error", err)
 		errc = <-w.deriveQuit
 	}
 	errc <- err
@@ -849,9 +851,7 @@ func (w *ledgerWallet) ledgerExchange(opcode ledgerOpcode, p1 ledgerParam1, p2 l
 			apdu = nil
 		}
 		// Send over to the device
-		if glog.V(logger.Detail) {
-			glog.Infof("-> %s: %x", w.device.Path, chunk)
-		}
+		w.logger.Trace("Data chunk sent to the Ledger", "chunk", hexutil.Bytes(chunk))
 		if _, err := w.device.Write(chunk); err != nil {
 			return nil, err
 		}
@@ -864,9 +864,8 @@ func (w *ledgerWallet) ledgerExchange(opcode ledgerOpcode, p1 ledgerParam1, p2 l
 		if _, err := io.ReadFull(w.device, chunk); err != nil {
 			return nil, err
 		}
-		if glog.V(logger.Detail) {
-			glog.Infof("<- %s: %x", w.device.Path, chunk)
-		}
+		w.logger.Trace("Data chunk received from the Ledger", "chunk", hexutil.Bytes(chunk))
+
 		// Make sure the transport header matches
 		if chunk[0] != 0x01 || chunk[1] != 0x01 || chunk[2] != 0x05 {
 			return nil, errReplyInvalidHeader