From 23a5d64fd059bb8bdf02781608a15b8b1bdbdfd2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A9ter=20Szil=C3=A1gyi?= Date: Wed, 22 Feb 2017 16:58:00 +0200 Subject: [PATCH] accounts, cmd: port packages over to the new logging system --- accounts/abi/bind/util.go | 9 +++++---- accounts/keystore/account_cache.go | 14 ++++++++------ accounts/keystore/watch.go | 12 ++++++------ accounts/usbwallet/ledger_hub.go | 3 ++- accounts/usbwallet/ledger_wallet.go | 27 ++++++++++++++------------ cmd/bootnode/main.go | 20 +++++++++---------- cmd/ethtest/main.go | 30 +++++++++++++++-------------- cmd/geth/accountcmd.go | 4 ++-- cmd/geth/accountcmd_test.go | 16 +++++++++------ cmd/utils/cmd.go | 9 --------- 10 files changed, 74 insertions(+), 70 deletions(-) diff --git a/accounts/abi/bind/util.go b/accounts/abi/bind/util.go index 88234688e..ca79694ef 100644 --- a/accounts/abi/bind/util.go +++ b/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 { diff --git a/accounts/keystore/account_cache.go b/accounts/keystore/account_cache.go index 11100ebc1..866f8ae7b 100644 --- a/accounts/keystore/account_cache.go +++ b/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}}) } diff --git a/accounts/keystore/watch.go b/accounts/keystore/watch.go index ff95a7cdc..ae97805be 100644 --- a/accounts/keystore/watch.go +++ b/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 != nil { - log.Trace(fmt.Sprintf("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) - 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 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 0dc53daf5..6086660f9 100644 --- a/accounts/usbwallet/ledger_wallet.go +++ b/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())) - defer log.Debug(fmt.Sprintf("%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 ( @@ -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())) - defer log.Debug(fmt.Sprintf("%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 ( @@ -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 { diff --git a/cmd/bootnode/main.go b/cmd/bootnode/main.go index f8cc77f83..31b2726be 100644 --- a/cmd/bootnode/main.go +++ b/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) } } diff --git a/cmd/ethtest/main.go b/cmd/ethtest/main.go index a107c701f..fcae668c6 100644 --- a/cmd/ethtest/main.go +++ b/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 { - log.Crit(fmt.Sprint(err)) - } + return runTestWithReader(flagTest, os.Stdin) } 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) } - } diff --git a/cmd/geth/accountcmd.go b/cmd/geth/accountcmd.go index b7c411e82..0b0be7938 100644 --- a/cmd/geth/accountcmd.go +++ b/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 { diff --git a/cmd/geth/accountcmd_test.go b/cmd/geth/accountcmd_test.go index 679a7ec30..adcb72454 100644 --- a/cmd/geth/accountcmd_test.go +++ b/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 289d485d9771714cce91d3393d764e1311907acc", + "Unlocked account", + "=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 289d485d9771714cce91d3393d764e1311907acc", + "Unlocked account", + "=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) { diff --git a/cmd/utils/cmd.go b/cmd/utils/cmd.go index e288f8bd2..5baa44980 100644 --- a/cmd/utils/cmd.go +++ b/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. -- GitLab