Merge pull request ethereum#3723 from karalabe/logger-updates-2

Logger updates

accounts/abi/bind/util.go

@@ -32,7 +32,7 @@ func WaitMined(ctx context.Context, b DeployBackend, tx *types.Transaction) (*ty
 	queryTicker := time.NewTicker(time.Second)
 	defer queryTicker.Stop()
 
-	logger := log.New("hash", tx.Hash().Hex()[:8])
+	logger := log.New("hash", tx.Hash())
 	for {
 		receipt, err := b.TransactionReceipt(ctx, tx.Hash())
 		if receipt != nil {

accounts/keystore/account_cache.go

@@ -262,7 +262,7 @@ func (ac *accountCache) scan() ([]accounts.Account, error) {
 		case err != nil:
 			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")
+			logger.Debug("Failed to decode keystore key", "err", "missing or zero address")
 		default:
 			addrs = append(addrs, accounts.Account{Address: addr, URL: accounts.URL{Scheme: KeyStoreScheme, Path: path}})
 		}

accounts/usbwallet/ledger_hub.go

@@ -121,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, logger: log.New("url", url)}
+			wallet := &ledgerWallet{url: &url, info: ledger, log: log.New("url", url)}
 
 			events = append(events, accounts.WalletEvent{Wallet: wallet, Arrive: true})
 			wallets = append(wallets, wallet)

accounts/usbwallet/ledger_wallet.go

@@ -124,7 +124,7 @@ type ledgerWallet struct {
 	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
+	log log.Logger // Contextual logger to tag the ledger with its id
 }
 
 // URL implements accounts.Wallet, returning the URL of the Ledger device.
@@ -222,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() {
-	w.logger.Debug("Ledger health-check started")
-	defer w.logger.Debug("Ledger health-check stopped")
+	w.log.Debug("Ledger health-check started")
+	defer w.log.Debug("Ledger health-check stopped")
 
 	// Execute heartbeat checks until termination or error
 	var (
@@ -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", "err", err)
+		w.log.Debug("Ledger health-check failed", "err", err)
 		errc = <-w.healthQuit
 	}
 	errc <- err
@@ -350,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() {
-	w.logger.Debug("Ledger self-derivation started")
-	defer w.logger.Debug("Ledger self-derivation stopped")
+	w.log.Debug("Ledger self-derivation started")
+	defer w.log.Debug("Ledger self-derivation stopped")
 
 	// Execute self-derivations until termination or error
 	var (
@@ -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", "err", err)
+					w.log.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", "err", err)
+				w.log.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", "err", err)
+				w.log.Warn("Ledger nonce retrieval failed", "err", err)
 				break
 			}
 			// If the next account is empty, stop self-derivation, but add it nonetheless
@@ -432,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) {
-				w.logger.Info("Ledger discovered new account", "address", nextAddr.Hex(), "path", path, "balance", balance, "nonce", nonce)
+				w.log.Info("Ledger discovered new account", "address", nextAddr, "path", path, "balance", balance, "nonce", nonce)
 			}
 			// Fetch the next potential account
 			if !empty {
@@ -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", "err", err)
+		w.log.Debug("Ledger self-derivation failed", "err", err)
 		errc = <-w.deriveQuit
 	}
 	errc <- err
@@ -851,7 +851,7 @@ func (w *ledgerWallet) ledgerExchange(opcode ledgerOpcode, p1 ledgerParam1, p2 l
 			apdu = nil
 		}
 		// Send over to the device
-		w.logger.Trace("Data chunk sent to the Ledger", "chunk", hexutil.Bytes(chunk))
+		w.log.Trace("Data chunk sent to the Ledger", "chunk", hexutil.Bytes(chunk))
 		if _, err := w.device.Write(chunk); err != nil {
 			return nil, err
 		}
@@ -864,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
 		}
-		w.logger.Trace("Data chunk received from the Ledger", "chunk", hexutil.Bytes(chunk))
+		w.log.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 {

common/types.go

@@ -47,8 +47,6 @@ func StringToHash(s string) Hash { return BytesToHash([]byte(s)) }
 func BigToHash(b *big.Int) Hash  { return BytesToHash(b.Bytes()) }
 func HexToHash(s string) Hash    { return BytesToHash(FromHex(s)) }
 
-// Don't use the default 'String' method in case we want to overwrite
-
 // Get the string representation of the underlying hash
 func (h Hash) Str() string   { return string(h[:]) }
 func (h Hash) Bytes() []byte { return h[:] }
@@ -144,6 +142,17 @@ func (a Address) Big() *big.Int { return new(big.Int).SetBytes(a[:]) }
 func (a Address) Hash() Hash    { return BytesToHash(a[:]) }
 func (a Address) Hex() string   { return hexutil.Encode(a[:]) }
 
+// String implements the stringer interface and is used also by the logger.
+func (a Address) String() string {
+	return a.Hex()
+}
+
+// Format implements fmt.Formatter, forcing the byte slice to be formatted as is,
+// without going through the stringer interface used for logging.
+func (a Address) Format(s fmt.State, c rune) {
+	fmt.Fprintf(s, "%"+string(c), a[:])
+}
+
 // Sets the address to the value of b. If b is larger than len(a) it will panic
 func (a *Address) SetBytes(b []byte) {
 	if len(b) > len(a) {

console/bridge.go

@@ -305,7 +305,7 @@ func setError(resp *otto.Object, code int, msg string) {
 func throwJSException(msg interface{}) otto.Value {
 	val, err := otto.ToValue(msg)
 	if err != nil {
-		log.Error(fmt.Sprintf("Failed to serialize JavaScript exception %v: %v", msg, err))
+		log.Error("Failed to serialize JavaScript exception", "exception", msg, "err", err)
 	}
 	panic(val)
 }

contracts/chequebook/cheque.go

@@ -37,6 +37,7 @@ import (
 
 	"github.com/ethereum/go-ethereum/accounts/abi/bind"
 	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/common/hexutil"
 	"github.com/ethereum/go-ethereum/contracts/chequebook/contract"
 	"github.com/ethereum/go-ethereum/core/types"
 	"github.com/ethereum/go-ethereum/crypto"
@@ -104,6 +105,8 @@ type Chequebook struct {
 	txhash    string   // tx hash of last deposit tx
 	threshold *big.Int // threshold that triggers autodeposit if not nil
 	buffer    *big.Int // buffer to keep on top of balance for fork protection
+
+	log log.Logger // contextual logger with the contrac address embedded
 }
 
 func (self *Chequebook) String() string {
@@ -135,19 +138,20 @@ func NewChequebook(path string, contractAddr common.Address, prvKey *ecdsa.Priva
 		owner:        transactOpts.From,
 		contract:     chbook,
 		session:      session,
+		log:          log.New("contract", contractAddr),
 	}
 
 	if (contractAddr != common.Address{}) {
 		self.setBalanceFromBlockChain()
-		log.Trace(fmt.Sprintf("new chequebook initialised from %s (owner: %v, balance: %s)", contractAddr.Hex(), self.owner.Hex(), self.balance.String()))
+		self.log.Trace("New chequebook initialised", "owner", self.owner, "balance", self.balance)
 	}
 	return
 }
 
 func (self *Chequebook) setBalanceFromBlockChain() {
 	balance, err := self.backend.BalanceAt(context.TODO(), self.contractAddr, nil)
 	if err != nil {
-		log.Error(fmt.Sprintf("can't get balance: %v", err))
+		log.Error("Failed to retrieve chequebook balance", "err", err)
 	} else {
 		self.balance.Set(balance)
 	}
@@ -160,7 +164,6 @@ func LoadChequebook(path string, prvKey *ecdsa.PrivateKey, backend Backend, chec
 	if err != nil {
 		return
 	}
-
 	self, _ = NewChequebook(path, common.Address{}, prvKey, backend)
 
 	err = json.Unmarshal(data, self)
@@ -170,8 +173,7 @@ func LoadChequebook(path string, prvKey *ecdsa.PrivateKey, backend Backend, chec
 	if checkBalance {
 		self.setBalanceFromBlockChain()
 	}
-
-	log.Trace(fmt.Sprintf("loaded chequebook (%s, owner: %v, balance: %v) initialised from %v", self.contractAddr.Hex(), self.owner.Hex(), self.balance, path))
+	log.Trace("Loaded chequebook from disk", "path", path)
 
 	return
 }
@@ -226,7 +228,7 @@ func (self *Chequebook) Save() (err error) {
 	if err != nil {
 		return err
 	}
-	log.Trace(fmt.Sprintf("saving chequebook (%s) to %v", self.contractAddr.Hex(), self.path))
+	self.log.Trace("Saving chequebook to disk", self.path)
 
 	return ioutil.WriteFile(self.path, data, os.ModePerm)
 }
@@ -339,12 +341,12 @@ func (self *Chequebook) deposit(amount *big.Int) (string, error) {
 	chbookRaw := &contract.ChequebookRaw{Contract: self.contract}
 	tx, err := chbookRaw.Transfer(depositTransactor)
 	if err != nil {
-		log.Warn(fmt.Sprintf("error depositing %d wei to chequebook (%s, balance: %v, target: %v): %v", amount, self.contractAddr.Hex(), self.balance, self.buffer, err))
+		self.log.Warn("Failed to fund chequebook", "amount", amount, "balance", self.balance, "target", self.buffer, "err", err)
 		return "", err
 	}
 	// assume that transaction is actually successful, we add the amount to balance right away
 	self.balance.Add(self.balance, amount)
-	log.Trace(fmt.Sprintf("deposited %d wei to chequebook (%s, balance: %v, target: %v)", amount, self.contractAddr.Hex(), self.balance, self.buffer))
+	self.log.Trace("Deposited funds to chequebook", "amount", amount, "balance", self.balance, "target", self.buffer)
 	return tx.Hash().Hex(), nil
 }
 
@@ -440,6 +442,7 @@ type Inbox struct {
 	maxUncashed *big.Int                    // threshold that triggers autocashing
 	cashed      *big.Int                    // cumulative amount cashed
 	cheque      *Cheque                     // last cheque, nil if none yet received
+	log         log.Logger                  // contextual logger with the contrac address embedded
 }
 
 // NewInbox creates an Inbox. An Inboxes is not persisted, the cumulative sum is updated
@@ -467,8 +470,9 @@ func NewInbox(prvKey *ecdsa.PrivateKey, contractAddr, beneficiary common.Address
 		signer:      signer,
 		session:     session,
 		cashed:      new(big.Int).Set(common.Big0),
+		log:         log.New("contract", contractAddr),
 	}
-	log.Trace(fmt.Sprintf("initialised inbox (%s -> %s) expected signer: %x", self.contract.Hex(), self.beneficiary.Hex(), crypto.FromECDSAPub(signer)))
+	self.log.Trace("New chequebook inbox initialized", "beneficiary", self.beneficiary, "signer", hexutil.Bytes(crypto.FromECDSAPub(signer)))
 	return
 }
 
@@ -490,7 +494,7 @@ func (self *Inbox) Stop() {
 func (self *Inbox) Cash() (txhash string, err error) {
 	if self.cheque != nil {
 		txhash, err = self.cheque.Cash(self.session)
-		log.Trace(fmt.Sprintf("cashing cheque (total: %v) on chequebook (%s) sending to %v", self.cheque.Amount, self.contract.Hex(), self.beneficiary.Hex()))
+		self.log.Trace("Cashing in chequebook cheque", "amount", self.cheque.Amount, "beneficiary", self.beneficiary)
 		self.cashed = self.cheque.Amount
 	}
 	return
@@ -574,15 +578,15 @@ func (self *Inbox) Receive(promise swap.Promise) (*big.Int, error) {
 				self.Cash()
 			}
 		}
-		log.Trace(fmt.Sprintf("received cheque of %v wei in inbox (%s, uncashed: %v)", amount, self.contract.Hex(), uncashed))
+		self.log.Trace("Received cheque in chequebook inbox", "amount", amount, "uncashed", uncashed)
 	}
 
 	return amount, err
 }
 
 // Verify verifies cheque for signer, contract, beneficiary, amount, valid signature.
 func (self *Cheque) Verify(signerKey *ecdsa.PublicKey, contract, beneficiary common.Address, sum *big.Int) (*big.Int, error) {
-	log.Trace(fmt.Sprintf("verify cheque: %v - sum: %v", self, sum))
+	log.Trace("Verifying chequebook cheque", "cheque", self, "sum", sum)
 	if sum == nil {
 		return nil, fmt.Errorf("invalid amount")
 	}

contracts/release/release.go

@@ -127,10 +127,10 @@ func (r *ReleaseService) checker() {
 			version, err := r.oracle.CurrentVersion(opts)
 			if err != nil {
 				if err == bind.ErrNoCode {
-					log.Debug(fmt.Sprintf("Release oracle not found at %x", r.config.Oracle))
+					log.Debug("Release oracle not found", "contract", r.config.Oracle)
 					continue
 				}
-				log.Error(fmt.Sprintf("Failed to retrieve current release: %v", err))
+				log.Error("Failed to retrieve current release", "err", err)
 				continue
 			}
 			// Version was successfully retrieved, notify if newer than ours
@@ -143,13 +143,14 @@ func (r *ReleaseService) checker() {
 				howtofix := fmt.Sprintf("Please check https://github.com/ethereum/go-ethereum/releases for new releases")
 				separator := strings.Repeat("-", len(warning))
 
-				log.Warn(fmt.Sprint(separator))
-				log.Warn(fmt.Sprint(warning))
-				log.Warn(fmt.Sprint(howtofix))
-				log.Warn(fmt.Sprint(separator))
+				log.Warn(separator)
+				log.Warn(warning)
+				log.Warn(howtofix)
+				log.Warn(separator)
 			} else {
-				log.Debug(fmt.Sprintf("Client v%d.%d.%d-%x seems up to date with upstream v%d.%d.%d-%x",
-					r.config.Major, r.config.Minor, r.config.Patch, r.config.Commit[:4], version.Major, version.Minor, version.Patch, version.Commit[:4]))
+				log.Debug("Client seems up to date with upstream",
+					"local", fmt.Sprintf("v%d.%d.%d-%x", r.config.Major, r.config.Minor, r.config.Patch, r.config.Commit[:4]),
+					"upstream", fmt.Sprintf("v%d.%d.%d-%x", version.Major, version.Minor, version.Patch, version.Commit[:4]))
 			}
 
 		// If termination was requested, return

core/block_validator.go

@@ -170,7 +170,7 @@ func (v *BlockValidator) VerifyUncles(block, parent *types.Block) error {
 			for h := range ancestors {
 				branch += fmt.Sprintf("  O - %x\n  |\n", h)
 			}
-			log.Info(fmt.Sprint(branch))
+			log.Warn(branch)
 			return UncleError("uncle[%d](%x) is ancestor", i, hash[:4])
 		}