From e82e86a4b751f37dc23f9966cd1d410f872ba70f Mon Sep 17 00:00:00 2001 From: yahtoo Date: Wed, 27 Feb 2019 11:09:59 +0800 Subject: [PATCH] Optimize log printing (#1590) --- account/accounts.go | 1 + account/image.go | 5 ++- account/utxo_keeper.go | 2 +- api/api.go | 9 +++-- api/txfeeds.go | 4 +- blockchain/pseudohsm/image.go | 9 +++-- blockchain/pseudohsm/keycache.go | 9 +++-- blockchain/txbuilder/rawtxsig_witness.go | 2 +- blockchain/txbuilder/signature_witness.go | 2 +- blockchain/txbuilder/txbuilder.go | 4 +- blockchain/txfeed/txfeed.go | 5 ++- cmd/bytomd/commands/init.go | 4 +- cmd/bytomd/commands/run_node.go | 5 ++- mining/cpuminer/cpuminer.go | 6 ++- mining/mining.go | 4 +- net/http/httpjson/io.go | 4 +- net/http/reqid/reqid.go | 3 +- netsync/handle.go | 6 +-- netsync/peer.go | 10 +++++ node/node.go | 11 ++++-- p2p/connection/connection.go | 27 ++++++------- p2p/discover/database.go | 18 ++++----- p2p/discover/net.go | 65 +++++++++++++++---------------- p2p/discover/ntp.go | 10 ++--- p2p/discover/table.go | 16 +++----- p2p/discover/ticket.go | 28 ++++++------- p2p/discover/topic.go | 4 +- p2p/discover/udp.go | 17 ++++---- p2p/listener.go | 2 +- p2p/peer.go | 12 ++++-- p2p/switch.go | 26 +++++++------ protocol/block.go | 14 +++---- protocol/orphan_manage.go | 4 +- protocol/protocol.go | 2 +- protocol/tx.go | 2 +- protocol/txpool.go | 7 ++-- version/version.go | 2 + wallet/annotated.go | 2 +- wallet/indexer.go | 2 +- wallet/unconfirmed.go | 6 +-- wallet/utxo.go | 14 +++---- wallet/wallet.go | 8 ++-- 42 files changed, 212 insertions(+), 181 deletions(-) diff --git a/account/accounts.go b/account/accounts.go index 6325a662..8e892732 100644 --- a/account/accounts.go +++ b/account/accounts.go @@ -32,6 +32,7 @@ const ( // HardenedKeyStart bip32 hierarchical deterministic wallets // keys with index ≥ 0x80000000 are hardened keys HardenedKeyStart = 0x80000000 + logModule = "account" ) var ( diff --git a/account/image.go b/account/image.go index 0a7b1156..3562c5e9 100644 --- a/account/image.go +++ b/account/image.go @@ -52,8 +52,9 @@ func (m *Manager) Restore(image *Image) error { for _, slice := range image.Slice { if existed := m.db.Get(Key(slice.Account.ID)); existed != nil { log.WithFields(log.Fields{ - "alias": slice.Account.Alias, - "id": slice.Account.ID, + "module": logModule, + "alias": slice.Account.Alias, + "id": slice.Account.ID, }).Warning("skip restore account due to already existed") continue } diff --git a/account/utxo_keeper.go b/account/utxo_keeper.go index f0fdf156..9fa62ea8 100644 --- a/account/utxo_keeper.go +++ b/account/utxo_keeper.go @@ -219,7 +219,7 @@ func (uk *utxoKeeper) findUtxos(accountID string, assetID *bc.AssetID, useUnconf for utxoIter.Next() { u := &UTXO{} if err := json.Unmarshal(utxoIter.Value(), u); err != nil { - log.WithField("err", err).Error("utxoKeeper findUtxos fail on unmarshal utxo") + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("utxoKeeper findUtxos fail on unmarshal utxo") continue } appendUtxo(u) diff --git a/api/api.go b/api/api.go index c6945cfe..e460eeea 100644 --- a/api/api.go +++ b/api/api.go @@ -41,7 +41,8 @@ const ( // SUCCESS indicates the rpc calling is successful. SUCCESS = "success" // FAIL indicated the rpc calling is failed. - FAIL = "fail" + FAIL = "fail" + logModule = "api" ) // Response describes the response standard. @@ -153,7 +154,7 @@ func (a *API) initServer(config *cfg.Config) { // StartServer start the server func (a *API) StartServer(address string) { - log.WithField("api address:", address).Info("Rpc listen") + log.WithFields(log.Fields{"module": logModule, "api address:": address}).Info("Rpc listen") listener, err := net.Listen("tcp", address) if err != nil { cmn.Exit(cmn.Fmt("Failed to register tcp port: %v", err)) @@ -164,7 +165,7 @@ func (a *API) StartServer(address string) { // we call it. go func() { if err := a.server.Serve(listener); err != nil { - log.WithField("error", errors.Wrap(err, "Serve")).Error("Rpc server") + log.WithFields(log.Fields{"module": logModule, "error": errors.Wrap(err, "Serve")}).Error("Rpc server") } }() } @@ -357,7 +358,7 @@ func AuthHandler(handler http.Handler, accessTokens *accesstoken.CredentialStore // TODO(tessr): check that this path exists; return early if this path isn't legit req, err := authenticator.Authenticate(req) if err != nil { - log.WithField("error", errors.Wrap(err, "Serve")).Error("Authenticate fail") + log.WithFields(log.Fields{"module": logModule, "error": errors.Wrap(err, "Serve")}).Error("Authenticate fail") err = errors.WithDetail(errNotAuthenticated, err.Error()) errorFormatter.Write(req.Context(), rw, err) return diff --git a/api/txfeeds.go b/api/txfeeds.go index 9aee2fe8..9f783175 100644 --- a/api/txfeeds.go +++ b/api/txfeeds.go @@ -16,7 +16,7 @@ func (a *API) createTxFeed(ctx context.Context, in struct { Filter string `json:"filter"` }) Response { if err := a.txFeedTracker.Create(ctx, in.Alias, in.Filter); err != nil { - log.WithField("error", err).Error("Add TxFeed Failed") + log.WithFields(log.Fields{"module": logModule, "error": err}).Error("Add TxFeed Failed") return NewErrorResponse(err) } return NewSuccessResponse(nil) @@ -58,7 +58,7 @@ func (a *API) updateTxFeed(ctx context.Context, in struct { return NewErrorResponse(err) } if err := a.txFeedTracker.Create(ctx, in.Alias, in.Filter); err != nil { - log.WithField("error", err).Error("Update TxFeed Failed") + log.WithFields(log.Fields{"module": logModule, "error": err}).Error("Update TxFeed Failed") return NewErrorResponse(err) } return NewSuccessResponse(nil) diff --git a/blockchain/pseudohsm/image.go b/blockchain/pseudohsm/image.go index 30536013..2bc2a16f 100644 --- a/blockchain/pseudohsm/image.go +++ b/blockchain/pseudohsm/image.go @@ -12,6 +12,8 @@ import ( "github.com/bytom/crypto/ed25519/chainkd" ) +const logModule = "pseudohsm" + // KeyImage is the struct for hold export key data type KeyImage struct { XKeys []*encryptedKeyJSON `json:"xkeys"` @@ -52,9 +54,10 @@ func (h *HSM) Restore(image *KeyImage) error { copy(xPub[:], data) if h.cache.hasKey(xPub) { log.WithFields(log.Fields{ - "alias": xKey.Alias, - "id": xKey.ID, - "xPub": xKey.XPub, + "module": logModule, + "alias": xKey.Alias, + "id": xKey.ID, + "xPub": xKey.XPub, }).Warning("skip restore key due to already existed") continue } diff --git a/blockchain/pseudohsm/keycache.go b/blockchain/pseudohsm/keycache.go index 7af88056..02e244ee 100644 --- a/blockchain/pseudohsm/keycache.go +++ b/blockchain/pseudohsm/keycache.go @@ -169,7 +169,7 @@ func (kc *keyCache) find(xpub XPub) (XPub, error) { func (kc *keyCache) reload() { keys, err := kc.scan() if err != nil { - log.WithField("load keys error", err).Error("can't load keys") + log.WithFields(log.Fields{"module": logModule, "load keys error": err}).Error("can't load keys") } kc.all = keys sort.Sort(kc.all) @@ -179,7 +179,7 @@ func (kc *keyCache) reload() { for _, k := range keys { kc.byPubs[k.XPub] = append(kc.byPubs[k.XPub], k) } - log.WithField("cache has keys:", len(kc.all)).Debug("reloaded keys") + log.WithFields(log.Fields{"module": logModule, "cache has keys:": len(kc.all)}).Debug("reloaded keys") } func (kc *keyCache) scan() ([]XPub, error) { @@ -214,9 +214,10 @@ func (kc *keyCache) scan() ([]XPub, error) { err = json.NewDecoder(buf).Decode(&keyJSON) switch { case err != nil: - log.WithField("decode json err", err).Errorf("can't decode key %s: %v", path, err) + log.WithFields(log.Fields{"module": logModule, "decode json err": err}).Errorf("can't decode key %s: %v", path, err) + case (keyJSON.Alias == ""): - log.WithField("can't decode key, key path:", path).Warn("missing or void alias") + log.WithFields(log.Fields{"module": logModule, "can't decode key, key path:": path}).Warn("missing or void alias") default: keys = append(keys, XPub{XPub: keyJSON.XPub, Alias: keyJSON.Alias, File: path}) } diff --git a/blockchain/txbuilder/rawtxsig_witness.go b/blockchain/txbuilder/rawtxsig_witness.go index 750d36cb..d5df57eb 100644 --- a/blockchain/txbuilder/rawtxsig_witness.go +++ b/blockchain/txbuilder/rawtxsig_witness.go @@ -40,7 +40,7 @@ func (sw *RawTxSigWitness) sign(ctx context.Context, tpl *Template, index uint32 } sigBytes, err := signFn(ctx, keyID.XPub, path, tpl.Hash(index).Byte32(), auth) if err != nil { - log.WithField("err", err).Warningf("computing signature %d", i) + log.WithFields(log.Fields{"module": logModule, "err": err}).Warningf("computing signature %d", i) continue } diff --git a/blockchain/txbuilder/signature_witness.go b/blockchain/txbuilder/signature_witness.go index ebdb3fb0..233b7720 100644 --- a/blockchain/txbuilder/signature_witness.go +++ b/blockchain/txbuilder/signature_witness.go @@ -86,7 +86,7 @@ func (sw *SignatureWitness) sign(ctx context.Context, tpl *Template, index uint3 } sigBytes, err := signFn(ctx, keyID.XPub, path, h, auth) if err != nil { - log.WithField("err", err).Warningf("computing signature %d", i) + log.WithFields(log.Fields{"module": logModule, "err": err}).Warningf("computing signature %d", i) continue } diff --git a/blockchain/txbuilder/txbuilder.go b/blockchain/txbuilder/txbuilder.go index fc741c65..9660ae70 100644 --- a/blockchain/txbuilder/txbuilder.go +++ b/blockchain/txbuilder/txbuilder.go @@ -17,6 +17,8 @@ import ( "github.com/bytom/protocol/vm" ) +const logModule = "txbuilder" + // errors var ( //ErrBadRefData means invalid reference data @@ -54,7 +56,7 @@ func Build(ctx context.Context, tx *types.TxData, actions []Action, maxTime time for i, action := range actions { err := action.Build(ctx, &builder) if err != nil { - log.WithFields(log.Fields{"action index": i, "error": err}).Error("Loop tx's action") + log.WithFields(log.Fields{"module": logModule, "action index": i, "error": err}).Error("Loop tx's action") errs = append(errs, errors.WithDetailf(err, "action index %v", i)) } } diff --git a/blockchain/txfeed/txfeed.go b/blockchain/txfeed/txfeed.go index b5fa5dad..d19f7f04 100644 --- a/blockchain/txfeed/txfeed.go +++ b/blockchain/txfeed/txfeed.go @@ -20,6 +20,7 @@ import ( const ( //FilterNumMax max txfeed filter amount. FilterNumMax = 1024 + logModule = "txfeed" ) var ( @@ -264,7 +265,7 @@ func (t *Tracker) Get(ctx context.Context, alias string) (*TxFeed, error) { //Delete delete txfeed with alias. func (t *Tracker) Delete(ctx context.Context, alias string) error { - log.WithField("delete", alias).Info("delete txfeed") + log.WithFields(log.Fields{"module": logModule, "delete": alias}).Info("delete txfeed") if alias == "" { return errors.WithDetail(ErrEmptyAlias, "del transaction feed with empty alias") @@ -312,7 +313,7 @@ func (t *Tracker) TxFilter(tx *types.Tx) error { if err != nil { return err } - log.WithField("filter", string(b)).Info("find new tx match filter") + log.WithFields(log.Fields{"module:": logModule, "filter": string(b)}).Info("find new tx match filter") t.txfeedCh <- tx } } diff --git a/cmd/bytomd/commands/init.go b/cmd/bytomd/commands/init.go index a3edadd6..ea565395 100644 --- a/cmd/bytomd/commands/init.go +++ b/cmd/bytomd/commands/init.go @@ -25,7 +25,7 @@ func init() { func initFiles(cmd *cobra.Command, args []string) { configFilePath := path.Join(config.RootDir, "config.toml") if _, err := os.Stat(configFilePath); !os.IsNotExist(err) { - log.WithField("config", configFilePath).Info("Already exists config file.") + log.WithFields(log.Fields{"module": logModule, "config": configFilePath}).Info("Already exists config file.") return } @@ -36,5 +36,5 @@ func initFiles(cmd *cobra.Command, args []string) { cfg.EnsureRoot(config.RootDir, "solonet") } - log.WithField("config", configFilePath).Info("Initialized bytom") + log.WithFields(log.Fields{"module": logModule, "config": configFilePath}).Info("Initialized bytom") } diff --git a/cmd/bytomd/commands/run_node.go b/cmd/bytomd/commands/run_node.go index 3e370e4f..54fc02f1 100644 --- a/cmd/bytomd/commands/run_node.go +++ b/cmd/bytomd/commands/run_node.go @@ -10,6 +10,8 @@ import ( "github.com/bytom/node" ) +const logModule = "cmd" + var runNodeCmd = &cobra.Command{ Use: "node", Short: "Run the bytomd", @@ -79,11 +81,12 @@ func runNode(cmd *cobra.Command, args []string) error { // Create & start node n := node.NewNode(config) if _, err := n.Start(); err != nil { - log.WithField("err", err).Fatal("failed to start node") + log.WithFields(log.Fields{"module": logModule, "err": err}).Fatal("failed to start node") } nodeInfo := n.NodeInfo() log.WithFields(log.Fields{ + "module": logModule, "version": nodeInfo.Version, "network": nodeInfo.Network, "duration": time.Since(startTime), diff --git a/mining/cpuminer/cpuminer.go b/mining/cpuminer/cpuminer.go index ffc39f87..6742e2eb 100644 --- a/mining/cpuminer/cpuminer.go +++ b/mining/cpuminer/cpuminer.go @@ -18,6 +18,7 @@ const ( maxNonce = ^uint64(0) // 2^64 - 1 defaultNumWorkers = 1 hashUpdateSecs = 1 + logModule = "cpuminer" ) // CPUMiner provides facilities for solving blocks (mining) using the CPU in @@ -94,6 +95,7 @@ out: if m.solveBlock(block, ticker, quit) { if isOrphan, err := m.chain.ProcessBlock(block); err == nil { log.WithFields(log.Fields{ + "module": logModule, "height": block.BlockHeader.Height, "isOrphan": isOrphan, "tx": len(block.Transactions), @@ -101,10 +103,10 @@ out: // Broadcast the block and announce chain insertion event if err = m.eventDispatcher.Post(event.NewMinedBlockEvent{Block: block}); err != nil { - log.WithField("height", block.BlockHeader.Height).Errorf("Miner fail on post block, %v", err) + log.WithFields(log.Fields{"module": logModule, "height": block.BlockHeader.Height, "error": err}).Errorf("Miner fail on post block") } } else { - log.WithField("height", block.BlockHeader.Height).Errorf("Miner fail on ProcessBlock, %v", err) + log.WithFields(log.Fields{"module": logModule, "height": block.BlockHeader.Height, "error": err}).Errorf("Miner fail on ProcessBlock") } } } diff --git a/mining/mining.go b/mining/mining.go index 41f6c1c4..e635976d 100644 --- a/mining/mining.go +++ b/mining/mining.go @@ -19,6 +19,8 @@ import ( "github.com/bytom/protocol/vm/vmutil" ) +const logModule = "mining" + // createCoinbaseTx returns a coinbase transaction paying an appropriate subsidy // based on the passed block height to the provided address. When the address // is nil, the coinbase transaction will instead be redeemable by anyone. @@ -159,6 +161,6 @@ func NewBlockTemplate(c *protocol.Chain, txPool *protocol.TxPool, accountManager } func blkGenSkipTxForErr(txPool *protocol.TxPool, txHash *bc.Hash, err error) { - log.WithField("error", err).Error("mining block generation: skip tx due to") + log.WithFields(log.Fields{"module": logModule, "error": err}).Error("mining block generation: skip tx due to") txPool.RemoveTransaction(txHash) } diff --git a/net/http/httpjson/io.go b/net/http/httpjson/io.go index 9f9010d3..d2221dad 100644 --- a/net/http/httpjson/io.go +++ b/net/http/httpjson/io.go @@ -11,6 +11,8 @@ import ( log "github.com/sirupsen/logrus" ) +const logModule = "httpjson" + // ErrBadRequest indicates the user supplied malformed JSON input, // possibly including a datatype that doesn't match what we expected. var ErrBadRequest = errors.New("httpjson: bad request") @@ -42,7 +44,7 @@ func Write(ctx context.Context, w http.ResponseWriter, status int, v interface{} err := json.NewEncoder(w).Encode(Array(v)) if err != nil { - log.WithField("error", err).Error("Error encountered during writing the Content-Type header using status") + log.WithFields(log.Fields{"module": logModule, "error": err}).Error("Error encountered during writing the Content-Type header using status") } } diff --git a/net/http/reqid/reqid.go b/net/http/reqid/reqid.go index 6156741a..f850269e 100644 --- a/net/http/reqid/reqid.go +++ b/net/http/reqid/reqid.go @@ -28,6 +28,7 @@ const ( coreIDKey // pathKey is the key for the request path being handled. pathKey + logModule = "reqid" ) // New generates a random request ID. @@ -43,7 +44,7 @@ func New() string { b := make([]byte, l) _, err := rand.Read(b) if err != nil { - log.WithField("error", err).Info("error making reqID") + log.WithFields(log.Fields{"module": logModule, "error": err}).Info("error making reqID") } return hex.EncodeToString(b) } diff --git a/netsync/handle.go b/netsync/handle.go index e8857c00..b412bee7 100644 --- a/netsync/handle.go +++ b/netsync/handle.go @@ -326,11 +326,7 @@ func (sm *SyncManager) handleStatusResponseMsg(basePeer BasePeer, msg *StatusRes } if genesisHash := msg.GetGenesisHash(); sm.genesisHash != *genesisHash { - log.WithFields(log.Fields{ - "module": logModule, - "remote genesis": genesisHash.String(), - "local genesis": sm.genesisHash.String(), - }).Warn("fail hand shake due to differnt genesis") + log.WithFields(log.Fields{"module": logModule, "remote genesis": genesisHash.String(), "local genesis": sm.genesisHash.String()}).Warn("fail hand shake due to differnt genesis") return } diff --git a/netsync/peer.go b/netsync/peer.go index f96ee1d4..586be2e7 100644 --- a/netsync/peer.go +++ b/netsync/peer.go @@ -3,6 +3,7 @@ package netsync import ( "encoding/hex" "net" + "reflect" "sync" log "github.com/sirupsen/logrus" @@ -118,6 +119,7 @@ func (p *peer) addFilterAddress(address []byte) { log.WithField("module", logModule).Warn("the size of filter address is greater than limit") return } + p.filterAdds.Add(hex.EncodeToString(address)) } @@ -385,6 +387,7 @@ func (ps *peerSet) broadcastMinedBlock(block *types.Block) error { continue } if ok := peer.TrySend(BlockchainChannel, struct{ BlockchainMessage }{msg}); !ok { + log.WithFields(log.Fields{"module": logModule, "peer": peer.Addr(), "type": reflect.TypeOf(msg), "message": msg.String()}).Warning("send message to peer error") ps.removePeer(peer.ID()) continue } @@ -401,6 +404,7 @@ func (ps *peerSet) broadcastNewStatus(bestBlock, genesisBlock *types.Block) erro msg := NewStatusResponseMessage(&bestBlock.BlockHeader, &genesisHash) for _, peer := range peers { if ok := peer.TrySend(BlockchainChannel, struct{ BlockchainMessage }{msg}); !ok { + log.WithFields(log.Fields{"module": logModule, "peer": peer.Addr(), "type": reflect.TypeOf(msg), "message": msg.String()}).Warning("send message to peer error") ps.removePeer(peer.ID()) continue } @@ -420,6 +424,12 @@ func (ps *peerSet) broadcastTx(tx *types.Tx) error { continue } if ok := peer.TrySend(BlockchainChannel, struct{ BlockchainMessage }{msg}); !ok { + log.WithFields(log.Fields{ + "module": logModule, + "peer": peer.Addr(), + "type": reflect.TypeOf(msg), + "message": msg.String(), + }).Warning("send message to peer error") ps.removePeer(peer.ID()) continue } diff --git a/node/node.go b/node/node.go index 0b27d1cf..6585097b 100644 --- a/node/node.go +++ b/node/node.go @@ -35,7 +35,10 @@ import ( w "github.com/bytom/wallet" ) -const webHost = "http://127.0.0.1" +const ( + webHost = "http://127.0.0.1" + logModule = "node" +) // Node represent bytom node type Node struct { @@ -92,7 +95,7 @@ func NewNode(config *cfg.Config) *Node { txFeed = txfeed.NewTracker(txFeedDB, chain) if err = txFeed.Prepare(ctx); err != nil { - log.WithField("error", err).Error("start txfeed") + log.WithFields(log.Fields{"module": logModule, "error": err}).Error("start txfeed") return nil } @@ -107,7 +110,7 @@ func NewNode(config *cfg.Config) *Node { assets = asset.NewRegistry(walletDB, chain) wallet, err = w.NewWallet(walletDB, accounts, assets, hsm, chain, dispatcher) if err != nil { - log.WithField("error", err).Error("init NewWallet") + log.WithFields(log.Fields{"module": logModule, "error": err}).Error("init NewWallet") } // trigger rescan wallet @@ -186,7 +189,7 @@ func initLogFile(config *cfg.Config) { if err == nil { log.SetOutput(file) } else { - log.WithField("err", err).Info("using default") + log.WithFields(log.Fields{"module": logModule, "err": err}).Info("using default") } } diff --git a/p2p/connection/connection.go b/p2p/connection/connection.go index ee4e6a79..5a45ada7 100644 --- a/p2p/connection/connection.go +++ b/p2p/connection/connection.go @@ -36,6 +36,7 @@ const ( defaultRecvMessageCapacity = 22020096 // 21MB defaultRecvRate = int64(512000) // 500KB/s defaultSendTimeout = 10 * time.Second + logModule = "p2p/conn" ) type receiveCbFunc func(chID byte, msgBytes []byte) @@ -182,12 +183,12 @@ func (c *MConnection) Send(chID byte, msg interface{}) bool { channel, ok := c.channelsIdx[chID] if !ok { - log.WithField("chID", chID).Error("cannot send bytes due to unknown channel") + log.WithFields(log.Fields{"module": logModule, "chID": chID}).Error("cannot send bytes due to unknown channel") return false } if !channel.sendBytes(wire.BinaryBytes(msg)) { - log.WithFields(log.Fields{"chID": chID, "conn": c, "msg": msg}).Error("MConnection send failed") + log.WithFields(log.Fields{"module": logModule, "chID": chID, "conn": c, "msg": msg}).Error("MConnection send failed") return false } @@ -213,7 +214,7 @@ func (c *MConnection) TrySend(chID byte, msg interface{}) bool { channel, ok := c.channelsIdx[chID] if !ok { - log.WithField("chID", chID).Error("cannot send bytes due to unknown channel") + log.WithFields(log.Fields{"module": logModule, "chID": chID}).Error("cannot send bytes due to unknown channel") return false } @@ -233,7 +234,7 @@ func (c *MConnection) String() string { func (c *MConnection) flush() { if err := c.bufWriter.Flush(); err != nil { - log.WithField("error", err).Error("MConnection flush failed") + log.WithFields(log.Fields{"module": logModule, "error": err}).Error("MConnection flush failed") } } @@ -264,7 +265,7 @@ func (c *MConnection) recvRoutine() { c.recvMonitor.Update(int(n)) if err != nil { if c.IsRunning() { - log.WithFields(log.Fields{"conn": c, "error": err}).Error("Connection failed @ recvRoutine (reading byte)") + log.WithFields(log.Fields{"module": logModule, "conn": c, "error": err}).Error("Connection failed @ recvRoutine (reading byte)") c.conn.Close() c.stopForError(err) } @@ -274,14 +275,14 @@ func (c *MConnection) recvRoutine() { // Read more depending on packet type. switch pktType { case packetTypePing: - log.Debug("receive Ping") + log.WithFields(log.Fields{"module": logModule, "conn": c}).Debug("receive Ping") select { case c.pong <- struct{}{}: default: } case packetTypePong: - log.Debug("receive Pong") + log.WithFields(log.Fields{"module": logModule, "conn": c}).Debug("receive Pong") case packetTypeMsg: pkt, n, err := msgPacket{}, int(0), error(nil) @@ -289,7 +290,7 @@ func (c *MConnection) recvRoutine() { c.recvMonitor.Update(int(n)) if err != nil { if c.IsRunning() { - log.WithFields(log.Fields{"conn": c, "error": err}).Error("failed on recvRoutine") + log.WithFields(log.Fields{"module": logModule, "conn": c, "error": err}).Error("failed on recvRoutine") c.stopForError(err) } return @@ -303,7 +304,7 @@ func (c *MConnection) recvRoutine() { msgBytes, err := channel.recvMsgPacket(pkt) if err != nil { if c.IsRunning() { - log.WithFields(log.Fields{"conn": c, "error": err}).Error("failed on recvRoutine") + log.WithFields(log.Fields{"module": logModule, "conn": c, "error": err}).Error("failed on recvRoutine") c.stopForError(err) } return @@ -338,7 +339,7 @@ func (c *MConnection) sendMsgPacket() bool { n, err := leastChannel.writeMsgPacketTo(c.bufWriter) if err != nil { - log.WithField("error", err).Error("failed to write msgPacket") + log.WithFields(log.Fields{"module": logModule, "error": err}).Error("failed to write msgPacket") c.stopForError(err) return true } @@ -362,12 +363,12 @@ func (c *MConnection) sendRoutine() { channel.updateStats() } case <-c.pingTimer.C: - log.Debug("send Ping") + log.WithFields(log.Fields{"module": logModule, "conn": c}).Debug("send Ping") wire.WriteByte(packetTypePing, c.bufWriter, &n, &err) c.sendMonitor.Update(int(n)) c.flush() case <-c.pong: - log.Debug("send Pong") + log.WithFields(log.Fields{"module": logModule, "conn": c}).Debug("send Pong") wire.WriteByte(packetTypePong, c.bufWriter, &n, &err) c.sendMonitor.Update(int(n)) c.flush() @@ -386,7 +387,7 @@ func (c *MConnection) sendRoutine() { return } if err != nil { - log.WithFields(log.Fields{"conn": c, "error": err}).Error("Connection failed @ sendRoutine") + log.WithFields(log.Fields{"module": logModule, "conn": c, "error": err}).Error("Connection failed @ sendRoutine") c.stopForError(err) return } diff --git a/p2p/discover/database.go b/p2p/discover/database.go index 15a4c87f..3f4168c1 100644 --- a/p2p/discover/database.go +++ b/p2p/discover/database.go @@ -96,7 +96,7 @@ func newPersistentNodeDB(path string, version int, self NodeID) (*nodeDB, error) // Version not found (i.e. empty cache), insert it if err = db.Put(nodeDBVersionKey, currentVer, nil); err != nil { if err := db.Close(); err != nil { - log.Warn(fmt.Sprintf("db close err %v", err)) + log.WithFields(log.Fields{"module": logModule, "error": err}).Warn(fmt.Sprintf("db close err")) } return nil, err } @@ -105,7 +105,7 @@ func newPersistentNodeDB(path string, version int, self NodeID) (*nodeDB, error) // Version present, flush if different if !bytes.Equal(blob, currentVer) { if err = db.Close(); err != nil { - log.Warn(fmt.Sprintf("db close err %v", err)) + log.WithFields(log.Fields{"module": logModule, "error": err}).Warn(fmt.Sprintf("db close err")) } if err = os.RemoveAll(path); err != nil { return nil, err @@ -175,13 +175,13 @@ func (db *nodeDB) node(id NodeID) *Node { key := makeKey(id, nodeDBDiscoverRoot) rawData, err := db.lvl.Get(key, nil) if err != nil { - log.Warn(fmt.Sprintf("get node rawdata err %v", err)) + log.WithFields(log.Fields{"module": logModule, "error": err}).Warn(fmt.Sprintf("get node rawdata err")) return nil } wire.ReadBinary(node, bytes.NewReader(rawData), 0, &n, &err) if err != nil { - log.Warn(fmt.Sprintf("key %x (%T) %v", key, node, err)) + log.WithFields(log.Fields{"module": logModule, "key": key, "node": node, "error": err}).Warn("get node from db err") return nil } @@ -238,7 +238,7 @@ func (db *nodeDB) expirer() { select { case <-tick.C: if err := db.expireNodes(); err != nil { - log.Error(fmt.Sprintf("Failed to expire nodedb items: %v", err)) + log.WithFields(log.Fields{"module": logModule, "error": err}).Error("Failed to expire nodedb items") } case <-db.quit: return @@ -325,7 +325,7 @@ seek: // of hitting all existing nodes in very small databases. ctr := id[0] if _, err := rand.Read(id[:]); err != nil { - log.Warn("get rand date:", err) + log.WithFields(log.Fields{"module": logModule, "error": err}).Warn("get rand date") } id[0] = ctr + id[0]%16 it.Seek(makeKey(id, nodeDBDiscoverRoot)) @@ -355,7 +355,7 @@ func (db *nodeDB) fetchTopicRegTickets(id NodeID) (issued, used uint32) { key := makeKey(id, nodeDBTopicRegTickets) blob, err := db.lvl.Get(key, nil) if err != nil { - log.Warn("db get raw data:", err) + log.WithFields(log.Fields{"module": logModule, "error": err}).Warn("db get raw data") } if len(blob) != 8 { @@ -391,7 +391,7 @@ func nextNode(it iterator.Iterator) *Node { wire.ReadBinary(node, bytes.NewReader(it.Value()), 0, &n, &err) if err != nil { - log.Error("invalid node:", id, err) + log.WithFields(log.Fields{"module": logModule, "id": id, "error": err}).Error("invalid node") continue } @@ -404,6 +404,6 @@ func nextNode(it iterator.Iterator) *Node { func (db *nodeDB) close() { close(db.quit) if err := db.lvl.Close(); err != nil { - log.Warn("db close err:", err) + log.WithFields(log.Fields{"module": logModule, "error": err}).Warn("db close err") } } diff --git a/p2p/discover/net.go b/p2p/discover/net.go index 4dbea0ee..ef067fc2 100644 --- a/p2p/discover/net.go +++ b/p2p/discover/net.go @@ -2,6 +2,7 @@ package discover import ( "bytes" + "encoding/hex" "errors" "fmt" "net" @@ -401,26 +402,25 @@ loop: select { case <-net.closeReq: - log.Debug("<-net.closeReq") + log.WithFields(log.Fields{"module": logModule}).Debug("close request") break loop // Ingress packet handling. case pkt := <-net.read: - //fmt.Println("read", pkt.ev) - log.Debug("<-net.read") + log.WithFields(log.Fields{"module": logModule}).Debug("read from net") n := net.internNode(&pkt) prestate := n.state status := "ok" if err := net.handle(n, pkt.ev, &pkt); err != nil { status = err.Error() } - log.Debug("", "msg", net.tab.count, pkt.ev, pkt.remoteID[:8], pkt.remoteAddr, prestate, n.state, status) + log.WithFields(log.Fields{"module": logModule, "node num": net.tab.count, "event": pkt.ev, "remote id": hex.EncodeToString(pkt.remoteID[:8]), "remote addr": pkt.remoteAddr, "pre state": prestate, "node state": n.state, "status": status}).Debug("handle ingress msg") // TODO: persist state if n.state goes >= known, delete if it goes <= known // State transition timeouts. case timeout := <-net.timeout: - log.Debug("<-net.timeout") + log.WithFields(log.Fields{"module": logModule}).Debug("net timeout") if net.timeoutTimers[timeout] == nil { // Stale timer (was aborted). continue @@ -431,24 +431,24 @@ loop: if err := net.handle(timeout.node, timeout.ev, nil); err != nil { status = err.Error() } - log.Debug("", "msg", net.tab.count, timeout.ev, timeout.node.ID[:8], timeout.node.addr(), prestate, timeout.node.state, status) + log.WithFields(log.Fields{"module": logModule, "node num": net.tab.count, "event": timeout.ev, "node id": hex.EncodeToString(timeout.node.ID[:8]), "node addr": timeout.node.addr(), "pre state": prestate, "node state": timeout.node.state, "status": status}).Debug("handle timeout") // Querying. case q := <-net.queryReq: - log.Debug("<-net.queryReq") + log.WithFields(log.Fields{"module": logModule}).Debug("net query request") if !q.start(net) { q.remote.deferQuery(q) } // Interacting with the table. case f := <-net.tableOpReq: - log.Debug("<-net.tableOpReq") + log.WithFields(log.Fields{"module": logModule}).Debug("net table operate request") f() net.tableOpResp <- struct{}{} // Topic registration stuff. case req := <-net.topicRegisterReq: - log.Debug("<-net.topicRegisterReq") + log.WithFields(log.Fields{"module": logModule, "topic": req.topic}).Debug("net topic register request") if !req.add { net.ticketStore.removeRegisterTopic(req.topic) continue @@ -459,7 +459,7 @@ loop: // determination for new topics. // if topicRegisterLookupDone == nil { if topicRegisterLookupTarget.target == (common.Hash{}) { - log.Debug("topicRegisterLookupTarget == null") + log.WithFields(log.Fields{"module": logModule, "topic": req.topic}).Debug("topic register lookup target null") if topicRegisterLookupTick.Stop() { <-topicRegisterLookupTick.C } @@ -469,7 +469,7 @@ loop: } case nodes := <-topicRegisterLookupDone: - log.Debug("<-topicRegisterLookupDone") + log.WithFields(log.Fields{"module": logModule}).Debug("topic register lookup done") net.ticketStore.registerLookupDone(topicRegisterLookupTarget, nodes, func(n *Node) []byte { net.ping(n, n.addr()) return n.pingEcho @@ -480,7 +480,7 @@ loop: topicRegisterLookupDone = nil case <-topicRegisterLookupTick.C: - log.Debug("<-topicRegisterLookupTick") + log.WithFields(log.Fields{"module": logModule}).Debug("topic register lookup tick") if (topicRegisterLookupTarget.target == common.Hash{}) { target, delay := net.ticketStore.nextRegisterLookup() topicRegisterLookupTarget = target @@ -493,14 +493,13 @@ loop: } case <-nextRegisterTime: - log.Debug("<-nextRegisterTime") + log.WithFields(log.Fields{"module": logModule}).Debug("next register time") net.ticketStore.ticketRegistered(*nextTicket) - //fmt.Println("sendTopicRegister", nextTicket.t.node.addr().String(), nextTicket.t.topics, nextTicket.idx, nextTicket.t.pong) net.conn.sendTopicRegister(nextTicket.t.node, nextTicket.t.topics, nextTicket.idx, nextTicket.t.pong) case req := <-net.topicSearchReq: if refreshDone == nil { - log.Debug("<-net.topicSearchReq") + log.WithFields(log.Fields{"module": logModule, "topic": req.topic}).Debug("net topic rearch req") info, ok := searchInfo[req.topic] if ok { if req.delay == time.Duration(0) { @@ -558,7 +557,7 @@ loop: }) case <-statsDump.C: - log.Debug("<-statsDump.C") + log.WithFields(log.Fields{"module": logModule}).Debug("stats dump clock") /*r, ok := net.ticketStore.radius[testTopic] if !ok { fmt.Printf("(%x) no radius @ %v\n", net.tab.self.ID[:8], time.Now()) @@ -574,20 +573,20 @@ loop: if printTestImgLogs { rad := r.radius / (maxRadius/1000000 + 1) minrad := r.minRadius / (maxRadius/1000000 + 1) - fmt.Printf("*R %d %v %016x %v\n", tm/1000000, topic, net.tab.self.sha[:8], rad) - fmt.Printf("*MR %d %v %016x %v\n", tm/1000000, topic, net.tab.self.sha[:8], minrad) + log.WithFields(log.Fields{"module": logModule}).Debug("*R %d %v %016x %v\n", tm/1000000, topic, net.tab.self.sha[:8], rad) + log.WithFields(log.Fields{"module": logModule}).Debug("*MR %d %v %016x %v\n", tm/1000000, topic, net.tab.self.sha[:8], minrad) } } for topic, t := range net.topictab.topics { wp := t.wcl.nextWaitPeriod(tm) if printTestImgLogs { - fmt.Printf("*W %d %v %016x %d\n", tm/1000000, topic, net.tab.self.sha[:8], wp/1000000) + log.WithFields(log.Fields{"module": logModule}).Debug("*W %d %v %016x %d\n", tm/1000000, topic, net.tab.self.sha[:8], wp/1000000) } } // Periodic / lookup-initiated bucket refresh. case <-refreshTimer.C: - log.Debug("<-refreshTimer.C") + log.WithFields(log.Fields{"module": logModule}).Debug("refresh timer clock") // TODO: ideally we would start the refresh timer after // fallback nodes have been set for the first time. if refreshDone == nil { @@ -601,7 +600,7 @@ loop: bucketRefreshTimer.Reset(bucketRefreshInterval) }() case newNursery := <-net.refreshReq: - log.Debug("<-net.refreshReq") + log.WithFields(log.Fields{"module": logModule}).Debug("net refresh request") if newNursery != nil { net.nursery = newNursery } @@ -611,7 +610,7 @@ loop: } net.refreshResp <- refreshDone case <-refreshDone: - log.Debug("<-net.refreshDone", "table size", net.tab.count) + log.WithFields(log.Fields{"module": logModule, "table size": net.tab.count}).Debug("net refresh done") if net.tab.count != 0 { refreshDone = nil list := searchReqWhenRefreshDone @@ -627,9 +626,7 @@ loop: } } } - log.Debug("loop stopped") - - log.Debug(fmt.Sprintf("shutting down")) + log.WithFields(log.Fields{"module": logModule}).Debug("loop stopped,shutting down") if net.conn != nil { net.conn.Close() } @@ -659,7 +656,7 @@ func (net *Network) refresh(done chan<- struct{}) { seeds = net.nursery } if len(seeds) == 0 { - log.Debug("no seed nodes found") + log.WithFields(log.Fields{"module": logModule}).Debug("no seed nodes found") time.AfterFunc(time.Second*10, func() { close(done) }) return } @@ -774,14 +771,14 @@ func (n *nodeNetGuts) startNextQuery(net *Network) { func (q *findnodeQuery) start(net *Network) bool { // Satisfy queries against the local node directly. if q.remote == net.tab.self { - log.Debug("findnodeQuery self") + log.WithFields(log.Fields{"module": logModule}).Debug("findnodeQuery self") closest := net.tab.closest(common.BytesToHash(q.target[:]), bucketSize) q.reply <- closest.entries return true } if q.remote.state.canQuery && q.remote.pendingNeighbours == nil { - log.Debug("findnodeQuery", "remote peer:", q.remote.ID, "targetID:", q.target) + log.WithFields(log.Fields{"module": logModule, "remote peer": q.remote.ID, "targetID": q.target}).Debug("find node query") net.conn.sendFindnodeHash(q.remote, q.target) net.timedEvent(respTimeout, q.remote, neighboursTimeout) q.remote.pendingNeighbours = q @@ -791,7 +788,7 @@ func (q *findnodeQuery) start(net *Network) bool { // Initiate the transition to known. // The request will be sent later when the node reaches known state. if q.remote.state == unknown { - log.Debug("findnodeQuery", "id:", q.remote.ID, "status:", "unknown->verifyinit") + log.WithFields(log.Fields{"module": logModule, "id": q.remote.ID, "status": "unknown->verify init"}).Debug("find node query") net.transition(q.remote, verifyinit) } return false @@ -1096,14 +1093,14 @@ func (net *Network) ping(n *Node, addr *net.UDPAddr) { //fmt.Println(" not sent") return } - log.Debug("Pinging remote node", "node", n.ID) + log.WithFields(log.Fields{"module": logModule, "node": n.ID}).Debug("Pinging remote node") n.pingTopics = net.ticketStore.regTopicSet() n.pingEcho = net.conn.sendPing(n, addr, n.pingTopics) net.timedEvent(respTimeout, n, pongTimeout) } func (net *Network) handlePing(n *Node, pkt *ingressPacket) { - log.Debug("Handling remote ping", "node", n.ID) + log.WithFields(log.Fields{"module": logModule, "node": n.ID}).Debug("Handling remote ping") ping := pkt.data.(*ping) n.TCP = ping.From.TCP t := net.topictab.getTicket(n, ping.Topics) @@ -1118,7 +1115,7 @@ func (net *Network) handlePing(n *Node, pkt *ingressPacket) { } func (net *Network) handleKnownPong(n *Node, pkt *ingressPacket) error { - log.Debug("Handling known pong", "node", n.ID) + log.WithFields(log.Fields{"module": logModule, "node": n.ID}).Debug("Handling known pong") net.abortTimedEvent(n, pongTimeout) now := Now() ticket, err := pongToTicket(now, n.pingTopics, n, pkt) @@ -1126,7 +1123,7 @@ func (net *Network) handleKnownPong(n *Node, pkt *ingressPacket) error { // fmt.Printf("(%x) ticket: %+v\n", net.tab.self.ID[:8], pkt.data) net.ticketStore.addTicket(now, pkt.data.(*pong).ReplyTok, ticket) } else { - log.Debug("Failed to convert pong to ticket", "err", err) + log.WithFields(log.Fields{"module": logModule, "error": err}).Debug("Failed to convert pong to ticket") } n.pingEcho = nil n.pingTopics = nil @@ -1243,7 +1240,7 @@ func (net *Network) handleNeighboursPacket(n *Node, pkt *ingressPacket) error { for i, rn := range req.Nodes { nn, err := net.internNodeFromNeighbours(pkt.remoteAddr, rn) if err != nil { - log.Debug(fmt.Sprintf("invalid neighbour (%v) from %x@%v: %v", rn.IP, n.ID[:8], pkt.remoteAddr, err)) + log.WithFields(log.Fields{"module": logModule, "ip": rn.IP, "id:": n.ID[:8], "addr:": pkt.remoteAddr, "error": err}).Debug("invalid neighbour") continue } nodes[i] = nn diff --git a/p2p/discover/ntp.go b/p2p/discover/ntp.go index 222620f8..1064bc10 100644 --- a/p2p/discover/ntp.go +++ b/p2p/discover/ntp.go @@ -38,12 +38,12 @@ func checkClockDrift() { howtofix := fmt.Sprintf("Please enable network time synchronisation in system settings") separator := strings.Repeat("-", len(warning)) - log.Warn(separator) - log.Warn(warning) - log.Warn(howtofix) - log.Warn(separator) + log.WithFields(log.Fields{"module": logModule}).Warn(separator) + log.WithFields(log.Fields{"module": logModule}).Warn(warning) + log.WithFields(log.Fields{"module": logModule}).Warn(howtofix) + log.WithFields(log.Fields{"module": logModule}).Warn(separator) } else { - log.Debug(fmt.Sprintf("Sanity NTP check reported %v drift, all ok", drift)) + log.WithFields(log.Fields{"module": logModule, "drift": drift}).Debug(fmt.Sprintf("Sanity NTP check reported all ok")) } } diff --git a/p2p/discover/table.go b/p2p/discover/table.go index 02061b57..62a00e68 100644 --- a/p2p/discover/table.go +++ b/p2p/discover/table.go @@ -9,10 +9,11 @@ package discover import ( "crypto/rand" "encoding/binary" - "fmt" "net" "sort" + log "github.com/sirupsen/logrus" + "github.com/bytom/common" "github.com/bytom/crypto" ) @@ -50,8 +51,6 @@ func newTable(ourID NodeID, ourAddr *net.UDPAddr) *Table { return tab } -const printTable = false - // chooseBucketRefreshTarget selects random refresh targets to keep all Kademlia // buckets filled with live connections and keep the network topology healthy. // This requires selecting addresses closer to our own with a higher probability @@ -64,16 +63,11 @@ const printTable = false // used buckets. func (tab *Table) chooseBucketRefreshTarget() common.Hash { entries := 0 - if printTable { - fmt.Println() - fmt.Println("self ", "id:", tab.self.ID, " hex:", crypto.Sha256Hash(tab.self.ID[:]).Hex()) - } + log.WithFields(log.Fields{"module": logModule, "self id:": tab.self.ID, "hex": crypto.Sha256Hash(tab.self.ID[:]).Hex()}).Debug() for i, b := range &tab.buckets { entries += len(b.entries) - if printTable { - for _, e := range b.entries { - fmt.Println(i, e.state, e.addr().String(), e.ID.String(), e.sha.Hex()) - } + for _, e := range b.entries { + log.WithFields(log.Fields{"module": logModule, "bucket": i, "status": e.state, "addr": e.addr().String(), "id": e.ID.String(), "hex": e.sha.Hex()}).Debug() } } diff --git a/p2p/discover/ticket.go b/p2p/discover/ticket.go index 378b8eaa..10de0374 100644 --- a/p2p/discover/ticket.go +++ b/p2p/discover/ticket.go @@ -104,7 +104,7 @@ func ticketToPong(t *ticket, pong *pong) { pong.Expiration = uint64(t.issueTime / AbsTime(time.Second)) pong.TopicHash, _, err = wireHash(t.topics) if err != nil { - log.Error("wireHash err:", err) + log.WithFields(log.Fields{"module": logModule, "error": err}).Error("wireHash err") } pong.TicketSerial = t.serial pong.WaitPeriods = make([]uint32, len(t.regTime)) @@ -168,7 +168,7 @@ func newTicketStore() *ticketStore { // addTopic starts tracking a topic. If register is true, // the local node will register the topic and tickets will be collected. func (s *ticketStore) addTopic(topic Topic, register bool) { - log.Debug("Adding discovery topic", "topic", topic, "register", register) + log.WithFields(log.Fields{"module": logModule, "topic": topic, "register": register}).Debug("Adding discovery topic") if s.radius[topic] == nil { s.radius[topic] = newTopicRadius(topic) } @@ -192,9 +192,9 @@ func (s *ticketStore) removeSearchTopic(t Topic) { // removeRegisterTopic deletes all tickets for the given topic. func (s *ticketStore) removeRegisterTopic(topic Topic) { - log.Debug("Removing discovery topic", "topic", topic) + log.WithFields(log.Fields{"module": logModule, "topic": topic}).Debug("Removing discovery topic") if s.tickets[topic] == nil { - log.Warn("Removing non-existent discovery topic", "topic", topic) + log.WithFields(log.Fields{"module": logModule, "topic": topic}).Warn("Removing non-existent discovery topic") return } for _, list := range s.tickets[topic].buckets { @@ -239,13 +239,13 @@ func (s *ticketStore) nextRegisterLookup() (lookupInfo, time.Duration) { // If the topic needs more tickets, return it if s.tickets[topic].nextLookup < Now() { next, delay := s.radius[topic].nextTarget(false), 100*time.Millisecond - log.Debug("Found discovery topic to register", "topic", topic, "target", next.target, "delay", delay) + log.WithFields(log.Fields{"module": logModule, "topic": topic, "target": next.target, "delay": delay}).Debug("Found discovery topic to register") return next, delay } } // No registration topics found or all exhausted, sleep delay := 40 * time.Second - log.Debug("No topic found to register", "delay", delay) + log.WithFields(log.Fields{"module": logModule, "delay": delay}).Debug("No topic found to register") return lookupInfo{}, delay } @@ -264,7 +264,7 @@ func (s *ticketStore) nextSearchLookup(topic Topic) lookupInfo { func (s *ticketStore) ticketsInWindow(topic Topic) []ticketRef { // Sanity check that the topic still exists before operating on it if s.tickets[topic] == nil { - log.Warn("Listing non-existing discovery tickets", "topic", topic) + log.WithFields(log.Fields{"module": logModule, "topic": topic}).Warn("Listing non-existing discovery tickets") return nil } // Gather all the tickers in the next time window @@ -274,7 +274,7 @@ func (s *ticketStore) ticketsInWindow(topic Topic) []ticketRef { for idx := timeBucket(0); idx < timeWindow; idx++ { tickets = append(tickets, buckets[s.lastBucketFetched+idx]...) } - log.Debug("Retrieved discovery registration tickets", "topic", topic, "from", s.lastBucketFetched, "tickets", len(tickets)) + log.WithFields(log.Fields{"module": logModule, "topic": topic, "from": s.lastBucketFetched, "tickets": len(tickets)}).Debug("Retrieved discovery registration tickets") return tickets } @@ -315,7 +315,7 @@ func (s *ticketStore) addTicketRef(r ticketRef) { topic := r.t.topics[r.idx] tickets := s.tickets[topic] if tickets == nil { - log.Warn("Adding ticket to non-existent topic", "topic", topic) + log.WithFields(log.Fields{"module": logModule, "topic": topic}).Warn("Adding ticket to non-existent topic") return } bucket := timeBucket(r.t.regTime[r.idx] / AbsTime(ticketTimeBucketLen)) @@ -409,7 +409,7 @@ func (s *ticketStore) nextRegisterableTicket() (*ticketRef, time.Duration) { // removeTicket removes a ticket from the ticket store func (s *ticketStore) removeTicketRef(ref ticketRef) { - log.Debug("Removing discovery ticket reference", "node", ref.t.node.ID, "serial", ref.t.serial) + log.WithFields(log.Fields{"module": logModule, "node": ref.t.node.ID, "serial": ref.t.serial}).Debug("Removing discovery ticket reference") // Make nextRegisterableTicket return the next available ticket. s.nextTicketCached = nil @@ -418,7 +418,7 @@ func (s *ticketStore) removeTicketRef(ref ticketRef) { tickets := s.tickets[topic] if tickets == nil { - log.Debug("Removing tickets from unknown topic", "topic", topic) + log.WithFields(log.Fields{"module": logModule, "topic": topic}).Debug("Removing tickets from unknown topic") return } bucket := timeBucket(ref.t.regTime[ref.idx] / AbsTime(ticketTimeBucketLen)) @@ -514,7 +514,7 @@ func (s *ticketStore) adjustWithTicket(now AbsTime, targetHash common.Hash, t *t } func (s *ticketStore) addTicket(localTime AbsTime, pingHash []byte, ticket *ticket) { - log.Debug("Adding discovery ticket", "node", ticket.node.ID, "serial", ticket.serial) + log.WithFields(log.Fields{"module": logModule, "node": ticket.node.ID, "serial": ticket.serial}).Debug("Adding discovery ticket") lastReq, ok := s.nodeLastReq[ticket.node] if !(ok && bytes.Equal(pingHash, lastReq.pingHash)) { @@ -558,9 +558,9 @@ func (s *ticketStore) addTicket(localTime AbsTime, pingHash []byte, ticket *tick func (s *ticketStore) getNodeTicket(node *Node) *ticket { if s.nodes[node] == nil { - log.Debug("Retrieving node ticket", "node", node.ID, "serial", nil) + log.WithFields(log.Fields{"module": logModule, "node": node.ID, "serial": nil}).Debug("Retrieving node ticket") } else { - log.Debug("Retrieving node ticket", "node", node.ID, "serial", s.nodes[node].serial) + log.WithFields(log.Fields{"module": logModule, "node": node.ID, "serial": s.nodes[node].serial}).Debug("Retrieving node ticket") } return s.nodes[node] } diff --git a/p2p/discover/topic.go b/p2p/discover/topic.go index 3a083c34..ef2d8a6d 100644 --- a/p2p/discover/topic.go +++ b/p2p/discover/topic.go @@ -225,10 +225,8 @@ func (t *topicTable) deleteEntry(e *topicEntry) { // It is assumed that topics and waitPeriods have the same length. func (t *topicTable) useTicket(node *Node, serialNo uint32, topics []Topic, idx int, issueTime uint64, waitPeriods []uint32) (registered bool) { - log.Debug("Using discovery ticket", "serial", serialNo, "topics", topics, "waits", waitPeriods) - //fmt.Println("useTicket", serialNo, topics, waitPeriods) + log.WithFields(log.Fields{"module": logModule, "serial": serialNo, "topics": topics, "waits": waitPeriods}).Debug("Using discovery ticket") t.collectGarbage() - n := t.getOrNewNode(node) if serialNo < n.lastUsedTicket { return false diff --git a/p2p/discover/udp.go b/p2p/discover/udp.go index 2f3e768d..5caf6a93 100644 --- a/p2p/discover/udp.go +++ b/p2p/discover/udp.go @@ -333,7 +333,7 @@ func ListenUDP(priv ed25519.PrivateKey, conn conn, realaddr *net.UDPAddr, nodeDB if err != nil { return nil, err } - log.Info("UDP listener up v5", "net", net.tab.self) + log.WithFields(log.Fields{"module": logModule, "net": net.tab.self}).Info("UDP listener up v5") transport.net = net go transport.readLoop() return net, nil @@ -425,9 +425,9 @@ func (t *udp) sendPacket(toid NodeID, toaddr *net.UDPAddr, ptype byte, req inter if err != nil { return hash, err } - log.Debug(fmt.Sprintf(">>> %v to %x@%v", nodeEvent(ptype), toid[:8], toaddr)) + log.WithFields(log.Fields{"module": logModule, "event": nodeEvent(ptype), "to id": hex.EncodeToString(toid[:8]), "to addr": toaddr}).Debug("send packet") if _, err = t.conn.WriteToUDP(packet, toaddr); err != nil { - log.Info(fmt.Sprint("UDP send failed:", err)) + log.WithFields(log.Fields{"module": logModule, "error": err}).Info(fmt.Sprint("UDP send failed")) } return hash, err } @@ -442,7 +442,7 @@ func encodePacket(priv ed25519.PrivateKey, ptype byte, req interface{}) (p, hash var size int wire.WriteJSON(req, b, &size, &err) if err != nil { - log.Error(fmt.Sprint("error encoding packet:", err)) + log.WithFields(log.Fields{"module": logModule, "error": err}).Error("error encoding packet") return nil, nil, err } packet := b.Bytes() @@ -468,11 +468,11 @@ func (t *udp) readLoop() { nbytes, from, err := t.conn.ReadFromUDP(buf) if netutil.IsTemporaryError(err) { // Ignore temporary read errors. - log.Debug(fmt.Sprintf("Temporary read error: %v", err)) + log.WithFields(log.Fields{"module": logModule, "error": err}).Debug("Temporary read error") continue } else if err != nil { // Shut down the loop for permament errors. - log.Debug(fmt.Sprintf("Read error: %v", err)) + log.WithFields(log.Fields{"module": logModule, "error": err}).Debug("Read error") return } t.handlePacket(from, buf[:nbytes]) @@ -482,8 +482,7 @@ func (t *udp) readLoop() { func (t *udp) handlePacket(from *net.UDPAddr, buf []byte) error { pkt := ingressPacket{remoteAddr: from} if err := decodePacket(buf, &pkt); err != nil { - log.Debug(fmt.Sprintf("Bad packet from %v: %v", from, err)) - //fmt.Println("bad packet", err) + log.WithFields(log.Fields{"module": logModule, "from": from, "error": err}).Error("Bad packet") return err } t.net.reqReadPacket(pkt) @@ -526,7 +525,7 @@ func decodePacket(buffer []byte, pkt *ingressPacket) error { var err error wire.ReadJSON(pkt.data, sigdata[1:], &err) if err != nil { - log.Error("wire readjson err:", err) + log.WithFields(log.Fields{"module": logModule, "error": err}).Error("wire readjson err") } return err diff --git a/p2p/listener.go b/p2p/listener.go index 5ab438c7..204b686b 100644 --- a/p2p/listener.go +++ b/p2p/listener.go @@ -153,7 +153,7 @@ func NewDefaultListener(protocol string, lAddr string, skipUPNP bool) (Listener, if !skipUPNP && (lAddrIP == "" || lAddrIP == "0.0.0.0") { extAddr, err = getUPNPExternalAddress(lAddrPort, listenerPort) upnpMap = err == nil - log.WithField("err", err).Info("get UPNP external address") + log.WithFields(log.Fields{"module": logModule, "err": err}).Info("get UPNP external address") } if extAddr == nil { diff --git a/p2p/peer.go b/p2p/peer.go index 42b88117..5960e77d 100644 --- a/p2p/peer.go +++ b/p2p/peer.go @@ -9,8 +9,8 @@ import ( "github.com/btcsuite/go-socks/socks" "github.com/pkg/errors" log "github.com/sirupsen/logrus" - crypto "github.com/tendermint/go-crypto" - wire "github.com/tendermint/go-wire" + "github.com/tendermint/go-crypto" + "github.com/tendermint/go-wire" cmn "github.com/tendermint/tmlibs/common" "github.com/tendermint/tmlibs/flowrate" @@ -155,7 +155,7 @@ func (pc *peerConn) HandshakeTimeout(ourNodeInfo *NodeInfo, timeout time.Duratio func() { var n int wire.ReadBinary(peerNodeInfo, pc.conn, maxNodeInfoSize, &n, &err2) - log.WithField("address", peerNodeInfo.ListenAddr).Info("Peer handshake") + log.WithFields(log.Fields{"module": logModule, "address": peerNodeInfo.ListenAddr}).Info("Peer handshake") }) if err1 != nil { return peerNodeInfo, errors.Wrap(err1, "Error during handshake/write") @@ -228,6 +228,12 @@ func (p *Peer) TrySend(chID byte, msg interface{}) bool { if !p.IsRunning() { return false } + + log.WithFields(log.Fields{ + "module": logModule, + "peer": p.Addr(), + "msg": msg, + }).Info("send message to peer") return p.mconn.TrySend(chID, msg) } diff --git a/p2p/switch.go b/p2p/switch.go index ab863a05..5d8018f3 100644 --- a/p2p/switch.go +++ b/p2p/switch.go @@ -27,6 +27,7 @@ const ( bannedPeerKey = "BannedPeer" defaultBanDuration = time.Hour * 1 minNumOutboundPeers = 3 + logModule = "p2p" ) //pre-define errors for connecting fail @@ -232,7 +233,7 @@ func (sw *Switch) AddListener(l Listener) { //DialPeerWithAddress dial node from net address func (sw *Switch) DialPeerWithAddress(addr *NetAddress) error { - log.Debug("Dialing peer address:", addr) + log.WithFields(log.Fields{"module": logModule, "address": addr}).Debug("Dialing peer") sw.dialing.Set(addr.IP.String(), addr) defer sw.dialing.Delete(addr.IP.String()) if err := sw.filterConnByIP(addr.IP.String()); err != nil { @@ -241,16 +242,16 @@ func (sw *Switch) DialPeerWithAddress(addr *NetAddress) error { pc, err := newOutboundPeerConn(addr, sw.nodePrivKey, sw.peerConfig) if err != nil { - log.WithFields(log.Fields{"address": addr, " err": err}).Error("DialPeer fail on newOutboundPeerConn") + log.WithFields(log.Fields{"module": logModule, "address": addr, " err": err}).Error("DialPeer fail on newOutboundPeerConn") return err } if err = sw.AddPeer(pc); err != nil { - log.WithFields(log.Fields{"address": addr, " err": err}).Error("DialPeer fail on switch AddPeer") + log.WithFields(log.Fields{"module": logModule, "address": addr, " err": err}).Error("DialPeer fail on switch AddPeer") pc.CloseConn() return err } - log.Debug("DialPeer added peer:", addr) + log.WithFields(log.Fields{"module": logModule, "address": addr, "peer num": sw.peers.Size()}).Debug("DialPeer added peer") return nil } @@ -309,7 +310,7 @@ func (sw *Switch) Peers() *PeerSet { // StopPeerForError disconnects from a peer due to external error. func (sw *Switch) StopPeerForError(peer *Peer, reason interface{}) { - log.WithFields(log.Fields{"peer": peer, " err": reason}).Debug("stopping peer for error") + log.WithFields(log.Fields{"module": logModule, "peer": peer, " err": reason}).Debug("stopping peer for error") sw.stopAndRemovePeer(peer, reason) } @@ -324,18 +325,19 @@ func (sw *Switch) addPeerWithConnection(conn net.Conn) error { peerConn, err := newInboundPeerConn(conn, sw.nodePrivKey, sw.Config.P2P) if err != nil { if err := conn.Close(); err != nil { - log.WithFields(log.Fields{"remote peer:": conn.RemoteAddr().String(), " err:": err}).Error("closes connection err") + log.WithFields(log.Fields{"module": logModule, "remote peer:": conn.RemoteAddr().String(), " err:": err}).Error("closes connection err") } return err } if err = sw.AddPeer(peerConn); err != nil { if err := conn.Close(); err != nil { - log.WithFields(log.Fields{"remote peer:": conn.RemoteAddr().String(), " err:": err}).Error("closes connection err") + log.WithFields(log.Fields{"module": logModule, "remote peer:": conn.RemoteAddr().String(), " err:": err}).Error("closes connection err") } return err } + log.WithFields(log.Fields{"module": logModule, "address": conn.RemoteAddr().String(), "peer num": sw.peers.Size()}).Debug("add inbound peer") return nil } @@ -401,7 +403,7 @@ func (sw *Switch) listenerRoutine(l Listener) { // disconnect if we alrady have MaxNumPeers if sw.peers.Size() >= sw.Config.P2P.MaxNumPeers { if err := inConn.Close(); err != nil { - log.WithFields(log.Fields{"remote peer:": inConn.RemoteAddr().String(), " err:": err}).Error("closes connection err") + log.WithFields(log.Fields{"module": logModule, "remote peer:": inConn.RemoteAddr().String(), " err:": err}).Error("closes connection err") } log.Info("Ignoring inbound connection: already have enough peers.") continue @@ -417,7 +419,7 @@ func (sw *Switch) listenerRoutine(l Listener) { func (sw *Switch) dialPeerWorker(a *NetAddress, wg *sync.WaitGroup) { if err := sw.DialPeerWithAddress(a); err != nil { - log.WithFields(log.Fields{"addr": a, "err": err}).Error("dialPeerWorker fail on dial peer") + log.WithFields(log.Fields{"module": logModule, "addr": a, "err": err}).Error("dialPeerWorker fail on dial peer") } wg.Done() } @@ -425,7 +427,7 @@ func (sw *Switch) dialPeerWorker(a *NetAddress, wg *sync.WaitGroup) { func (sw *Switch) ensureOutboundPeers() { numOutPeers, _, numDialing := sw.NumPeers() numToDial := (minNumOutboundPeers - (numOutPeers + numDialing)) - log.WithFields(log.Fields{"numOutPeers": numOutPeers, "numDialing": numDialing, "numToDial": numToDial}).Debug("ensure peers") + log.WithFields(log.Fields{"module": logModule, "numOutPeers": numOutPeers, "numDialing": numDialing, "numToDial": numToDial}).Debug("ensure peers") if numToDial <= 0 { return } @@ -475,7 +477,7 @@ func (sw *Switch) ensureOutboundPeersRoutine() { func (sw *Switch) startInitPeer(peer *Peer) error { // spawn send/recv routines if _, err := peer.Start(); err != nil { - log.WithFields(log.Fields{"remote peer:": peer.RemoteAddr, " err:": err}).Error("init peer err") + log.WithFields(log.Fields{"module": logModule, "remote peer:": peer.RemoteAddr, " err:": err}).Error("init peer err") } for _, reactor := range sw.reactors { @@ -495,6 +497,7 @@ func (sw *Switch) stopAndRemovePeer(peer *Peer, reason interface{}) { sentStatus, receivedStatus := peer.TrafficStatus() log.WithFields(log.Fields{ + "module": logModule, "address": peer.Addr().String(), "reason": reason, "duration": sentStatus.Duration.String(), @@ -502,5 +505,6 @@ func (sw *Switch) stopAndRemovePeer(peer *Peer, reason interface{}) { "total_received": receivedStatus.Bytes, "average_sent_rate": sentStatus.AvgRate, "average_received_rate": receivedStatus.AvgRate, + "peer num": sw.peers.Size(), }).Info("disconnect with peer") } diff --git a/protocol/block.go b/protocol/block.go index 72a2dd7b..b29a3d94 100644 --- a/protocol/block.go +++ b/protocol/block.go @@ -120,7 +120,7 @@ func (c *Chain) reorganizeChain(node *state.BlockNode) error { return err } - log.WithFields(log.Fields{"height": node.Height, "hash": node.Hash.String()}).Debug("detach from mainchain") + log.WithFields(log.Fields{"module": logModule, "height": node.Height, "hash": node.Hash.String()}).Debug("detach from mainchain") } for _, attachNode := range attachNodes { @@ -141,7 +141,7 @@ func (c *Chain) reorganizeChain(node *state.BlockNode) error { return err } - log.WithFields(log.Fields{"height": node.Height, "hash": node.Hash.String()}).Debug("attach from mainchain") + log.WithFields(log.Fields{"module": logModule, "height": node.Height, "hash": node.Hash.String()}).Debug("attach from mainchain") } return c.setState(node, utxoView) @@ -180,11 +180,11 @@ func (c *Chain) saveSubBlock(block *types.Block) *types.Block { for _, prevOrphan := range prevOrphans { orphanBlock, ok := c.orphanManage.Get(prevOrphan) if !ok { - log.WithFields(log.Fields{"hash": prevOrphan.String()}).Warning("saveSubBlock fail to get block from orphanManage") + log.WithFields(log.Fields{"module": logModule, "hash": prevOrphan.String()}).Warning("saveSubBlock fail to get block from orphanManage") continue } if err := c.saveBlock(orphanBlock); err != nil { - log.WithFields(log.Fields{"hash": prevOrphan.String(), "height": orphanBlock.Height}).Warning("saveSubBlock fail to save block") + log.WithFields(log.Fields{"module": logModule, "hash": prevOrphan.String(), "height": orphanBlock.Height}).Warning("saveSubBlock fail to save block") continue } @@ -224,7 +224,7 @@ func (c *Chain) blockProcesser() { func (c *Chain) processBlock(block *types.Block) (bool, error) { blockHash := block.Hash() if c.BlockExist(&blockHash) { - log.WithFields(log.Fields{"hash": blockHash.String(), "height": block.Height}).Info("block has been processed") + log.WithFields(log.Fields{"module": logModule, "hash": blockHash.String(), "height": block.Height}).Info("block has been processed") return c.orphanManage.BlockExist(&blockHash), nil } @@ -242,12 +242,12 @@ func (c *Chain) processBlock(block *types.Block) (bool, error) { bestNode := c.index.GetNode(&bestBlockHash) if bestNode.Parent == c.bestNode { - log.Debug("append block to the end of mainchain") + log.WithFields(log.Fields{"module": logModule}).Debug("append block to the end of mainchain") return false, c.connectBlock(bestBlock) } if bestNode.Height > c.bestNode.Height && bestNode.WorkSum.Cmp(c.bestNode.WorkSum) >= 0 { - log.Debug("start to reorganize chain") + log.WithFields(log.Fields{"module": logModule}).Debug("start to reorganize chain") return false, c.reorganizeChain(bestNode) } return false, nil diff --git a/protocol/orphan_manage.go b/protocol/orphan_manage.go index 166282f4..d250269d 100644 --- a/protocol/orphan_manage.go +++ b/protocol/orphan_manage.go @@ -58,14 +58,14 @@ func (o *OrphanManage) Add(block *types.Block) { } if len(o.orphan) >= numOrphanBlockLimit { - log.WithFields(log.Fields{"hash": blockHash.String(), "height": block.Height}).Info("the number of orphan blocks exceeds the limit") + log.WithFields(log.Fields{"module": logModule, "hash": blockHash.String(), "height": block.Height}).Info("the number of orphan blocks exceeds the limit") return } o.orphan[blockHash] = &orphanBlock{block, time.Now().Add(orphanBlockTTL)} o.prevOrphans[block.PreviousBlockHash] = append(o.prevOrphans[block.PreviousBlockHash], &blockHash) - log.WithFields(log.Fields{"hash": blockHash.String(), "height": block.Height}).Info("add block to orphan") + log.WithFields(log.Fields{"module": logModule, "hash": blockHash.String(), "height": block.Height}).Info("add block to orphan") } // Delete will delete the block from OrphanManage diff --git a/protocol/protocol.go b/protocol/protocol.go index 29b96282..aa24aff6 100644 --- a/protocol/protocol.go +++ b/protocol/protocol.go @@ -136,7 +136,7 @@ func (c *Chain) setState(node *state.BlockNode, view *state.UtxoViewpoint) error c.index.SetMainChain(node) c.bestNode = node - log.WithFields(log.Fields{"height": c.bestNode.Height, "hash": c.bestNode.Hash.String()}).Debug("chain best status has been update") + log.WithFields(log.Fields{"module": logModule, "height": c.bestNode.Height, "hash": c.bestNode.Hash.String()}).Debug("chain best status has been update") c.cond.Broadcast() return nil } diff --git a/protocol/tx.go b/protocol/tx.go index bbbe738d..4797c1fd 100644 --- a/protocol/tx.go +++ b/protocol/tx.go @@ -40,7 +40,7 @@ func (c *Chain) ValidateTx(tx *types.Tx) (bool, error) { } if err != nil { - log.WithFields(log.Fields{"tx_id": tx.Tx.ID.String(), "error": err}).Info("transaction status fail") + log.WithFields(log.Fields{"module": logModule, "tx_id": tx.Tx.ID.String(), "error": err}).Info("transaction status fail") } return c.txPool.ProcessTransaction(tx, err != nil, block.BlockHeader.Height, gasStatus.BTMValue) diff --git a/protocol/txpool.go b/protocol/txpool.go index 0916f161..edb6af03 100644 --- a/protocol/txpool.go +++ b/protocol/txpool.go @@ -20,6 +20,7 @@ import ( const ( MsgNewTx = iota MsgRemoveTx + logModule = "protocol" ) var ( @@ -138,7 +139,7 @@ func (tp *TxPool) RemoveTransaction(txHash *bc.Hash) { atomic.StoreInt64(&tp.lastUpdated, time.Now().Unix()) tp.eventDispatcher.Post(TxMsgEvent{TxMsg: &TxPoolMsg{TxDesc: txD, MsgType: MsgRemoveTx}}) - log.WithField("tx_id", txHash).Debug("remove tx from mempool") + log.WithFields(log.Fields{"module": logModule, "tx_id": txHash}).Debug("remove tx from mempool") } // GetTransaction return the TxDesc by hash @@ -255,7 +256,7 @@ func (tp *TxPool) addTransaction(txD *TxDesc) error { atomic.StoreInt64(&tp.lastUpdated, time.Now().Unix()) tp.eventDispatcher.Post(TxMsgEvent{TxMsg: &TxPoolMsg{TxDesc: txD, MsgType: MsgNewTx}}) - log.WithField("tx_id", tx.ID.String()).Debug("Add tx to mempool") + log.WithFields(log.Fields{"module": logModule, "tx_id": tx.ID.String()}).Debug("Add tx to mempool") return nil } @@ -302,7 +303,7 @@ func (tp *TxPool) processOrphans(txD *TxDesc) { processOrphan := processOrphans[0] requireParents, err := tp.checkOrphanUtxos(processOrphan.Tx) if err != nil { - log.WithField("err", err).Error("processOrphans got unexpect error") + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("processOrphans got unexpect error") continue } diff --git a/version/version.go b/version/version.go index b2016fd1..11367084 100644 --- a/version/version.go +++ b/version/version.go @@ -42,6 +42,7 @@ const ( noUpdate uint16 = iota hasUpdate hasMUpdate + logModule = "version" ) var ( @@ -112,6 +113,7 @@ func (s *UpdateStatus) CheckUpdate(localVerStr string, remoteVerStr string, remo } if s.versionStatus != noUpdate { log.WithFields(log.Fields{ + "module": logModule, "Current version": localVerStr, "Newer version": remoteVerStr, "seed": remoteAddr, diff --git a/wallet/annotated.go b/wallet/annotated.go index 2a49a3ff..9ac57c60 100644 --- a/wallet/annotated.go +++ b/wallet/annotated.go @@ -55,7 +55,7 @@ func (w *Wallet) getExternalDefinition(assetID *bc.AssetID) json.RawMessage { } if err := w.AssetReg.SaveAsset(externalAsset, alias); err != nil { - log.WithFields(log.Fields{"err": err, "assetID": alias}).Warning("fail on save external asset to internal asset DB") + log.WithFields(log.Fields{"module": logModule, "err": err, "assetID": alias}).Warning("fail on save external asset to internal asset DB") } return definitionByte } diff --git a/wallet/indexer.go b/wallet/indexer.go index f2b13405..dad3b64b 100644 --- a/wallet/indexer.go +++ b/wallet/indexer.go @@ -103,7 +103,7 @@ func (w *Wallet) indexTransactions(batch db.Batch, b *types.Block, txStatus *bc. for _, tx := range annotatedTxs { rawTx, err := json.Marshal(tx) if err != nil { - log.WithField("err", err).Error("inserting annotated_txs to db") + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("inserting annotated_txs to db") return err } diff --git a/wallet/unconfirmed.go b/wallet/unconfirmed.go index 2aba1e60..b616518f 100644 --- a/wallet/unconfirmed.go +++ b/wallet/unconfirmed.go @@ -36,7 +36,7 @@ func (a SortByTimestamp) Less(i, j int) bool { return a[i].Timestamp > a[j].Time // AddUnconfirmedTx handle wallet status update when tx add into txpool func (w *Wallet) AddUnconfirmedTx(txD *protocol.TxDesc) { if err := w.saveUnconfirmedTx(txD.Tx); err != nil { - log.WithField("err", err).Error("wallet fail on saveUnconfirmedTx") + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("wallet fail on saveUnconfirmedTx") } utxos := txOutToUtxos(txD.Tx, txD.StatusFail, 0) @@ -168,7 +168,7 @@ func (w *Wallet) delExpiredTxs() error { //delUnconfirmedTx periodically delete locally stored timeout did not confirm txs func (w *Wallet) delUnconfirmedTx() { if err := w.delExpiredTxs(); err != nil { - log.WithField("err", err).Error("wallet fail on delUnconfirmedTx") + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("wallet fail on delUnconfirmedTx") return } ticker := time.NewTicker(UnconfirmedTxCheckPeriod) @@ -176,7 +176,7 @@ func (w *Wallet) delUnconfirmedTx() { for { <-ticker.C if err := w.delExpiredTxs(); err != nil { - log.WithField("err", err).Error("wallet fail on delUnconfirmedTx") + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("wallet fail on delUnconfirmedTx") } } } diff --git a/wallet/utxo.go b/wallet/utxo.go index 5f60e908..6bb8216e 100644 --- a/wallet/utxo.go +++ b/wallet/utxo.go @@ -33,7 +33,7 @@ func (w *Wallet) GetAccountUtxos(accountID string, id string, unconfirmed, isSma for accountUtxoIter.Next() { accountUtxo := &account.UTXO{} if err := json.Unmarshal(accountUtxoIter.Value(), accountUtxo); err != nil { - log.WithField("err", err).Warn("GetAccountUtxos fail on unmarshal utxo") + log.WithFields(log.Fields{"module": logModule, "err": err}).Warn("GetAccountUtxos fail on unmarshal utxo") continue } @@ -48,7 +48,7 @@ func (w *Wallet) attachUtxos(batch db.Batch, b *types.Block, txStatus *bc.Transa for txIndex, tx := range b.Transactions { statusFail, err := txStatus.GetStatus(txIndex) if err != nil { - log.WithField("err", err).Error("attachUtxos fail on get tx status") + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("attachUtxos fail on get tx status") continue } @@ -70,7 +70,7 @@ func (w *Wallet) attachUtxos(batch db.Batch, b *types.Block, txStatus *bc.Transa outputUtxos := txOutToUtxos(tx, statusFail, validHeight) utxos := w.filterAccountUtxo(outputUtxos) if err := batchSaveUtxos(utxos, batch); err != nil { - log.WithField("err", err).Error("attachUtxos fail on batchSaveUtxos") + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("attachUtxos fail on batchSaveUtxos") } } } @@ -93,14 +93,14 @@ func (w *Wallet) detachUtxos(batch db.Batch, b *types.Block, txStatus *bc.Transa statusFail, err := txStatus.GetStatus(txIndex) if err != nil { - log.WithField("err", err).Error("detachUtxos fail on get tx status") + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("detachUtxos fail on get tx status") continue } inputUtxos := txInToUtxos(tx, statusFail) utxos := w.filterAccountUtxo(inputUtxos) if err := batchSaveUtxos(utxos, batch); err != nil { - log.WithField("err", err).Error("detachUtxos fail on batchSaveUtxos") + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("detachUtxos fail on batchSaveUtxos") return } } @@ -131,7 +131,7 @@ func (w *Wallet) filterAccountUtxo(utxos []*account.UTXO) []*account.UTXO { cp := &account.CtrlProgram{} if err := json.Unmarshal(data, cp); err != nil { - log.WithField("err", err).Error("filterAccountUtxo fail on unmarshal control program") + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("filterAccountUtxo fail on unmarshal control program") continue } @@ -172,7 +172,7 @@ func txInToUtxos(tx *types.Tx, statusFail bool) []*account.UTXO { resOut, err := tx.Output(*sp.SpentOutputId) if err != nil { - log.WithField("err", err).Error("txInToUtxos fail on get resOut") + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("txInToUtxos fail on get resOut") continue } diff --git a/wallet/wallet.go b/wallet/wallet.go index 08b2f56c..8a463306 100644 --- a/wallet/wallet.go +++ b/wallet/wallet.go @@ -126,7 +126,7 @@ func (w *Wallet) loadWalletInfo() error { func (w *Wallet) commitWalletInfo(batch db.Batch) error { rawWallet, err := json.Marshal(w.status) if err != nil { - log.WithField("err", err).Error("save wallet info") + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("save wallet info") return err } @@ -203,12 +203,12 @@ func (w *Wallet) walletUpdater() { for !w.chain.InMainChain(w.status.BestHash) { block, err := w.chain.GetBlockByHash(&w.status.BestHash) if err != nil { - log.WithField("err", err).Error("walletUpdater GetBlockByHash") + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("walletUpdater GetBlockByHash") return } if err := w.DetachBlock(block); err != nil { - log.WithField("err", err).Error("walletUpdater detachBlock stop") + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("walletUpdater detachBlock stop") return } } @@ -220,7 +220,7 @@ func (w *Wallet) walletUpdater() { } if err := w.AttachBlock(block); err != nil { - log.WithField("err", err).Error("walletUpdater AttachBlock stop") + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("walletUpdater AttachBlock stop") return } } -- 2.11.0