accounts, cmd: port packages over to the new logging system

accounts/abi/bind/util.go

@@ -29,18 +29,19 @@ import (
 // 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 {
-			log.Trace(fmt.Sprintf("tx %x error: %v", loghash, err))
+			logger.Trace("Receipt retrieval failed", "error", err)
 		} else {
-			log.Trace(fmt.Sprintf("tx %x not yet mined...", loghash))
+			logger.Trace("Transaction not yet mined")
 		}
 		// Wait for the next round.
 		select {

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(fmt.Sprintf("can't load keys: %v", err))
+		log.Debug("Failed to reload keystore contents", "error", err)
 	}
 	ac.all = accounts
 	sort.Sort(ac.all)
@@ -224,7 +224,7 @@ func (ac *accountCache) reload() {
 	case ac.notify <- struct{}{}:
 	default:
 	}
-	log.Debug(fmt.Sprintf("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) {
@@ -243,12 +243,14 @@ func (ac *accountCache) scan() ([]accounts.Account, error) {
 	for _, fi := range files {
 		path := filepath.Join(ac.keydir, fi.Name())
 		if skipKeyFile(fi) {
-			log.Trace(fmt.Sprintf("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 {
-			log.Trace(fmt.Sprint(err))
+			logger.Trace("Failed to open keystore file", "error", err)
 			continue
 		}
 		buf.Reset(fd)
@@ -258,9 +260,9 @@ func (ac *accountCache) scan() ([]accounts.Account, error) {
 		addr := common.HexToAddress(keyJSON.Address)
 		switch {
 		case err != nil:
-			log.Debug(fmt.Sprintf("can't decode key %s: %v", path, err))
+			logger.Debug("Failed to decode keystore key", "error", err)
 		case (addr == common.Address{}):
-			log.Debug(fmt.Sprintf("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}})
 		}

accounts/keystore/watch.go

@@ -19,7 +19,6 @@
 package keystore
 
 import (
-	"fmt"
 	"time"
 
 	"github.com/ethereum/go-ethereum/log"
@@ -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 := notify.Watch(w.ac.keydir, w.ev, notify.All); err != nil {
-	if err != nil {
+		logger.Trace("Failed to watch keystore folder", "error", err)
-		log.Trace(fmt.Sprintf("can't watch %s: %v", w.ac.keydir, err))
 		return
 	}
 	defer notify.Stop(w.ev)
-	log.Trace(fmt.Sprintf("now watching %s", w.ac.keydir))
+
-	defer log.Trace(fmt.Sprintf("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

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)

accounts/usbwallet/ledger_wallet.go

@@ -33,6 +33,7 @@ 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/log"
 	"github.com/ethereum/go-ethereum/rlp"
@@ -122,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.
@@ -219,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() {
-	log.Debug(fmt.Sprintf("%s health-check started", w.url.String()))
+	w.logger.Debug("Ledger health-check started")
-	defer log.Debug(fmt.Sprintf("%s health-check stopped", w.url.String()))
+	defer w.logger.Debug("Ledger health-check stopped")
 
 	// Execute heartbeat checks until termination or error
 	var (
@@ -259,7 +262,7 @@ func (w *ledgerWallet) heartbeat() {
 	}
 	// In case of error, wait for termination
 	if err != nil {
-		log.Debug(fmt.Sprintf("%s health-check failed: %v", w.url.String(), err))
+		w.logger.Debug("Ledger health-check failed", "error", err)
 		errc = <-w.healthQuit
 	}
 	errc <- err
@@ -347,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() {
-	log.Debug(fmt.Sprintf("%s self-derivation started", w.url.String()))
+	w.logger.Debug("Ledger self-derivation started")
-	defer log.Debug(fmt.Sprintf("%s self-derivation stopped", w.url.String()))
+	defer w.logger.Debug("Ledger self-derivation stopped")
 
 	// Execute self-derivations until termination or error
 	var (
@@ -393,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 {
-					log.Warn(fmt.Sprintf("%s self-derivation failed: %v", w.url.String(), err))
+					w.logger.Warn("Ledger account derivation failed", "error", err)
 					break
 				}
 			}
@@ -404,12 +407,12 @@ func (w *ledgerWallet) selfDerive() {
 			)
 			balance, err = w.deriveChain.BalanceAt(context, nextAddr, nil)
 			if err != nil {
-				log.Warn(fmt.Sprintf("%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 {
-				log.Warn(fmt.Sprintf("%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
@@ -429,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) {
-				log.Info(fmt.Sprintf("%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 {
@@ -468,7 +471,7 @@ func (w *ledgerWallet) selfDerive() {
 	}
 	// In case of error, wait for termination
 	if err != nil {
-		log.Debug(fmt.Sprintf("%s self-derivation failed: %s", w.url.String(), err))
+		w.logger.Debug("Ledger self-derivation failed", "error", err)
 		errc = <-w.deriveQuit
 	}
 	errc <- err
@@ -848,7 +851,7 @@ func (w *ledgerWallet) ledgerExchange(opcode ledgerOpcode, p1 ledgerParam1, p2 l
 			apdu = nil
 		}
 		// Send over to the device
-		log.Trace("", "msg", log.Lazy{Fn: func() string { return fmt.Sprintf("-> %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
 		}
@@ -861,7 +864,7 @@ func (w *ledgerWallet) ledgerExchange(opcode ledgerOpcode, p1 ledgerParam1, p2 l
 		if _, err := io.ReadFull(w.device, chunk); err != nil {
 			return nil, err
 		}
-		log.Trace("", "msg", log.Lazy{Fn: func() string { return fmt.Sprintf("<- %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 {

cmd/bootnode/main.go

@@ -56,28 +56,28 @@ func main() {
 
 	natm, err := nat.Parse(*natdesc)
 	if err != nil {
-		log.Crit(fmt.Sprintf("-nat: %v", err))
+		log.Crit("Failed to parse requested NAT", "error", err)
 	}
 	switch {
 	case *genKey != "":
 		nodeKey, err = crypto.GenerateKey()
 		if err != nil {
-			log.Crit(fmt.Sprintf("could not generate key: %v", err))
+			log.Crit("Failed to generate new key", "error", err)
 		}
 		if err = crypto.SaveECDSA(*genKey, nodeKey); err != nil {
-			log.Crit(fmt.Sprintf("%v", err))
+			log.Crit("Failed to save generated key", "error", err)
 		}
 	case *nodeKeyFile == "" && *nodeKeyHex == "":
-		log.Crit(fmt.Sprintf("Use -nodekey or -nodekeyhex to specify a private key"))
+		log.Crit("Use -nodekey or -nodekeyhex to load a private key")
 	case *nodeKeyFile != "" && *nodeKeyHex != "":
-		log.Crit(fmt.Sprintf("Options -nodekey and -nodekeyhex are mutually exclusive"))
+		log.Crit("Options -nodekey and -nodekeyhex are mutually exclusive")
 	case *nodeKeyFile != "":
 		if nodeKey, err = crypto.LoadECDSA(*nodeKeyFile); err != nil {
-			log.Crit(fmt.Sprintf("-nodekey: %v", err))
+			log.Crit("Failed to loading the key file", "path", *nodeKeyFile, "error", err)
 		}
 	case *nodeKeyHex != "":
 		if nodeKey, err = crypto.HexToECDSA(*nodeKeyHex); err != nil {
-			log.Crit(fmt.Sprintf("-nodekeyhex: %v", err))
+			log.Crit("Failed to parse the key hex", "hex", *nodeKeyHex, "error", err)
 		}
 	}
 
@@ -90,17 +90,17 @@ func main() {
 	if *netrestrict != "" {
 		restrictList, err = netutil.ParseNetlist(*netrestrict)
 		if err != nil {
-			log.Crit(fmt.Sprintf("-netrestrict: %v", err))
+			log.Crit("Failed to parse the network restrictions", "error", err)
 		}
 	}
 
 	if *runv5 {
 		if _, err := discv5.ListenUDP(nodeKey, *listenAddr, natm, "", restrictList); err != nil {
-			log.Crit(fmt.Sprintf("%v", err))
+			log.Crit("Failed to start the v5 discovery protocol", "error", err)
 		}
 	} else {
 		if _, err := discover.ListenUDP(nodeKey, *listenAddr, natm, "", restrictList); err != nil {
-			log.Crit(fmt.Sprintf("%v", err))
+			log.Crit("Failed to start the discovery protocol", "error", err)
 		}
 	}
 

cmd/ethtest/main.go

@@ -70,7 +70,8 @@ var (
 )
 
 func runTestWithReader(test string, r io.Reader) error {
-	log.Info(fmt.Sprint("runTest", test))
+	log.Info("Running test", "test", test)
+
 	var err error
 	switch strings.ToLower(test) {
 	case "bk", "block", "blocktest", "blockchaintest", "blocktests", "blockchaintests":
@@ -92,7 +93,8 @@ func runTestWithReader(test string, r io.Reader) error {
 }
 
 func getFiles(path string) ([]string, error) {
-	log.Info(fmt.Sprint("getFiles", path))
+	log.Info("Listing files", "path", path)
+
 	var files []string
 	f, err := os.Open(path)
 	if err != nil {
@@ -113,7 +115,7 @@ func getFiles(path string) ([]string, error) {
 			// only go 1 depth and leave directory entires blank
 			if !v.IsDir() && v.Name()[len(v.Name())-len(testExtension):len(v.Name())] == testExtension {
 				files[i] = filepath.Join(path, v.Name())
-				log.Info(fmt.Sprint("Found file", files[i]))
+				log.Info("Found test file", "file", files[i])
 			}
 		}
 	case mode.IsRegular():
@@ -134,7 +136,9 @@ func runSuite(test, file string) {
 	}
 
 	for _, curTest := range tests {
-		log.Info(fmt.Sprint("runSuite", curTest, file))
+		suiteLogger := log.New("suite", file, "test", curTest)
+		suiteLogger.Info("Running test suite")
+
 		var err error
 		var files []string
 		if test == defaultTest {
@@ -149,30 +153,31 @@ func runSuite(test, file string) {
 			files, err = getFiles(file)
 		}
 		if err != nil {
-			log.Crit(fmt.Sprint(err))
+			suiteLogger.Crit("Failed to gather files", "error", err)
 		}
 
 		if len(files) == 0 {
-			log.Warn("No files matched path")
+			suiteLogger.Warn("No files matched path")
 		}
 		for _, curFile := range files {
 			// Skip blank entries
 			if len(curFile) == 0 {
 				continue
 			}
+			testLogger := suiteLogger.New("file", curFile)
 
 			r, err := os.Open(curFile)
 			if err != nil {
-				log.Crit(fmt.Sprint(err))
+				testLogger.Crit("Failed to open file")
 			}
 			defer r.Close()
 
 			err = runTestWithReader(curTest, r)
 			if err != nil {
 				if continueOnError {
-					log.Error(fmt.Sprint(err))
+					testLogger.Error("Test failed, continuing", "error", err)
 				} else {
-					log.Crit(fmt.Sprint(err))
+					testLogger.Crit("Test failed, aborting", "error", err)
 				}
 			}
 		}
@@ -189,9 +194,7 @@ func setupApp(c *cli.Context) error {
 	if !useStdIn {
 		runSuite(flagTest, flagFile)
 	} else {
-		if err := runTestWithReader(flagTest, os.Stdin); err != nil {
+		return runTestWithReader(flagTest, os.Stdin)
-			log.Crit(fmt.Sprint(err))
-		}
 	}
 	return nil
 }
@@ -216,7 +219,6 @@ func main() {
 	}
 
 	if err := app.Run(os.Args); err != nil {
-		log.Crit(fmt.Sprint(err))
+		log.Crit("Failed to run the tester", "error", err)
 	}
-
 }

cmd/geth/accountcmd.go

@@ -204,11 +204,11 @@ func unlockAccount(ctx *cli.Context, ks *keystore.KeyStore, address string, i in
 		password := getPassPhrase(prompt, false, i, passwords)
 		err = ks.Unlock(account, password)
 		if err == nil {
-			log.Info(fmt.Sprintf("Unlocked account %x", account.Address))
+			log.Info("Unlocked account", "address", account.Address.Hex())
 			return account, password
 		}
 		if err, ok := err.(*keystore.AmbiguousAddrError); ok {
-			log.Info(fmt.Sprintf("Unlocked account %x", account.Address))
+			log.Info("Unlocked account", "address", account.Address.Hex())
 			return ambiguousAddrRecovery(ks, err, password), password
 		}
 		if err != keystore.ErrDecrypt {

cmd/geth/accountcmd_test.go

@@ -145,7 +145,8 @@ Passphrase: {{.InputLine "foobar"}}
 	geth.expectExit()
 
 	wantMessages := []string{
-		"Unlocked account f466859ead1932d743d622cb74fc058882e8648a",
+		"Unlocked account",
+		"=0xf466859ead1932d743d622cb74fc058882e8648a",
 	}
 	for _, m := range wantMessages {
 		if !strings.Contains(geth.stderrText(), m) {
@@ -189,8 +190,9 @@ Passphrase: {{.InputLine "foobar"}}
 	geth.expectExit()
 
 	wantMessages := []string{
-		"Unlocked account 7ef5a6135f1fd6a02593eedc869c6d41d934aef8",
+		"Unlocked account",
-		"Unlocked account 289d485d9771714cce91d3393d764e1311907acc",
+		"=0x7ef5a6135f1fd6a02593eedc869c6d41d934aef8",
+		"=0x289d485d9771714cce91d3393d764e1311907acc",
 	}
 	for _, m := range wantMessages {
 		if !strings.Contains(geth.stderrText(), m) {
@@ -208,8 +210,9 @@ func TestUnlockFlagPasswordFile(t *testing.T) {
 	geth.expectExit()
 
 	wantMessages := []string{
-		"Unlocked account 7ef5a6135f1fd6a02593eedc869c6d41d934aef8",
+		"Unlocked account",
-		"Unlocked account 289d485d9771714cce91d3393d764e1311907acc",
+		"=0x7ef5a6135f1fd6a02593eedc869c6d41d934aef8",
+		"=0x289d485d9771714cce91d3393d764e1311907acc",
 	}
 	for _, m := range wantMessages {
 		if !strings.Contains(geth.stderrText(), m) {
@@ -257,7 +260,8 @@ In order to avoid this warning, you need to remove the following duplicate key f
 	geth.expectExit()
 
 	wantMessages := []string{
-		"Unlocked account f466859ead1932d743d622cb74fc058882e8648a",
+		"Unlocked account",
+		"=0xf466859ead1932d743d622cb74fc058882e8648a",
 	}
 	for _, m := range wantMessages {
 		if !strings.Contains(geth.stderrText(), m) {

cmd/utils/cmd.go

@@ -40,15 +40,6 @@ const (
 	importBatchSize = 2500
 )
 
-func openLogFile(Datadir string, filename string) *os.File {
-	path := common.AbsolutePath(Datadir, filename)
-	file, err := os.OpenFile(path, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0666)
-	if err != nil {
-		panic(fmt.Sprintf("error opening log file '%s': %v", filename, err))
-	}
-	return file
-}
-
 // Fatalf formats a message to standard error and exits the program.
 // The message is also printed to standard output if standard error
 // is redirected to a different file.