From 9184249b393e4e332ae6a2f5d774880a88a9bfd6 Mon Sep 17 00:00:00 2001 From: Péter Szilágyi Date: Thu, 2 Mar 2017 15:06:16 +0200 Subject: Logger updates 3 (#3730) * accounts, cmd, eth, ethdb: port logs over to new system * ethdb: drop concept of cache distribution between dbs * eth: fix some log nitpicks to make them nicer --- eth/handler.go | 50 ++++++++++++++++++++++++-------------------------- 1 file changed, 24 insertions(+), 26 deletions(-) (limited to 'eth/handler.go') diff --git a/eth/handler.go b/eth/handler.go index bcb83ed90..a7f4be0b6 100644 --- a/eth/handler.go +++ b/eth/handler.go @@ -115,7 +115,7 @@ func NewProtocolManager(config *params.ChainConfig, fastSync bool, networkId int } // Figure out whether to allow fast sync or not if fastSync && blockchain.CurrentBlock().NumberU64() > 0 { - log.Info(fmt.Sprintf("blockchain not empty, fast sync disabled")) + log.Warn("Blockchain not empty, fast sync disabled") fastSync = false } if fastSync { @@ -178,7 +178,7 @@ func NewProtocolManager(config *params.ChainConfig, fastSync bool, networkId int manager.fetcher = fetcher.New(blockchain.GetBlockByHash, validator, manager.BroadcastBlock, heighter, inserter, manager.removePeer) if blockchain.Genesis().Hash().Hex() == defaultGenesisHash && networkId == 1 { - log.Debug(fmt.Sprint("Bad Block Reporting is enabled")) + log.Debug("Bad block reporting is enabled") manager.badBlockReportingEnabled = true } @@ -199,12 +199,12 @@ func (pm *ProtocolManager) removePeer(id string) { if peer == nil { return } - log.Debug(fmt.Sprint("Removing peer", id)) + log.Debug("Removing Ethereum peer", "peer", id) // Unregister the peer from the downloader and Ethereum peer set pm.downloader.UnregisterPeer(id) if err := pm.peers.Unregister(id); err != nil { - log.Error(fmt.Sprint("Removal failed:", err)) + log.Error("Peer removal failed", "peer", id, "err", err) } // Hard disconnect at the networking layer if peer != nil { @@ -226,7 +226,7 @@ func (pm *ProtocolManager) Start() { } func (pm *ProtocolManager) Stop() { - log.Info(fmt.Sprint("Stopping ethereum protocol handler...")) + log.Info("Stopping Ethereum protocol") pm.txSub.Unsubscribe() // quits txBroadcastLoop pm.minedBlockSub.Unsubscribe() // quits blockBroadcastLoop @@ -247,7 +247,7 @@ func (pm *ProtocolManager) Stop() { // Wait for all peer handler goroutines and the loops to come down. pm.wg.Wait() - log.Info(fmt.Sprint("Ethereum protocol handler stopped")) + log.Info("Ethereum protocol stopped") } func (pm *ProtocolManager) newPeer(pv int, p *p2p.Peer, rw p2p.MsgReadWriter) *peer { @@ -260,22 +260,20 @@ func (pm *ProtocolManager) handle(p *peer) error { if pm.peers.Len() >= pm.maxPeers { return p2p.DiscTooManyPeers } - - log.Debug(fmt.Sprintf("%v: peer connected [%s]", p, p.Name())) + p.Log().Debug("Ethereum peer connected", "name", p.Name()) // Execute the Ethereum handshake td, head, genesis := pm.blockchain.Status() if err := p.Handshake(pm.networkId, td, head, genesis); err != nil { - log.Debug(fmt.Sprintf("%v: handshake failed: %v", p, err)) + p.Log().Debug("Ethereum handshake failed", "err", err) return err } if rw, ok := p.rw.(*meteredMsgReadWriter); ok { rw.Init(p.version) } // Register the peer locally - log.Trace(fmt.Sprintf("%v: adding peer", p)) if err := pm.peers.Register(p); err != nil { - log.Error(fmt.Sprintf("%v: addition failed: %v", p, err)) + p.Log().Error("Ethereum peer registration failed", "err", err) return err } defer pm.removePeer(p.id) @@ -296,7 +294,7 @@ func (pm *ProtocolManager) handle(p *peer) error { } // Start a timer to disconnect if the peer doesn't reply in time p.forkDrop = time.AfterFunc(daoChallengeTimeout, func() { - log.Debug(fmt.Sprintf("%v: timed out DAO fork-check, dropping", p)) + p.Log().Debug("Timed out DAO fork-check, dropping") pm.removePeer(p.id) }) // Make sure it's cleaned up if the peer dies off @@ -310,7 +308,7 @@ func (pm *ProtocolManager) handle(p *peer) error { // main loop. handle incoming messages. for { if err := pm.handleMsg(p); err != nil { - log.Debug(fmt.Sprintf("%v: message handling failed: %v", p, err)) + p.Log().Debug("Message handling failed", "err", err) return err } } @@ -386,7 +384,7 @@ func (pm *ProtocolManager) handleMsg(p *peer) error { ) if next <= current { infos, _ := json.MarshalIndent(p.Peer.Info(), "", " ") - log.Warn(fmt.Sprintf("%v: GetBlockHeaders skip overflow attack (current %v, skip %v, next %v)\nMalicious peer infos: %s", p, current, query.Skip, next, infos)) + p.Log().Warn("GetBlockHeaders skip overflow attack", "current", current, "skip", query.Skip, "next", next, "attacker", infos) unknown = true } else { if header := pm.blockchain.GetHeaderByNumber(next); header != nil { @@ -434,7 +432,7 @@ func (pm *ProtocolManager) handleMsg(p *peer) error { } // If we're seemingly on the same chain, disable the drop timer if verifyDAO { - log.Debug(fmt.Sprintf("%v: seems to be on the same side of the DAO fork", p)) + p.Log().Debug("Seems to be on the same side of the DAO fork") p.forkDrop.Stop() p.forkDrop = nil return nil @@ -451,10 +449,10 @@ func (pm *ProtocolManager) handleMsg(p *peer) error { // Validate the header and either drop the peer or continue if err := core.ValidateDAOHeaderExtraData(pm.chainconfig, headers[0]); err != nil { - log.Debug(fmt.Sprintf("%v: verified to be on the other side of the DAO fork, dropping", p)) + p.Log().Debug("Verified to be on the other side of the DAO fork, dropping") return err } - log.Debug(fmt.Sprintf("%v: verified to be on the same side of the DAO fork", p)) + p.Log().Debug("Verified to be on the same side of the DAO fork") return nil } // Irrelevant of the fork checks, send the header to the fetcher just in case @@ -463,7 +461,7 @@ func (pm *ProtocolManager) handleMsg(p *peer) error { if len(headers) > 0 || !filter { err := pm.downloader.DeliverHeaders(p.id, headers) if err != nil { - log.Debug(fmt.Sprint(err)) + log.Debug("Failed to deliver headers", "err", err) } } @@ -516,7 +514,7 @@ func (pm *ProtocolManager) handleMsg(p *peer) error { if len(trasactions) > 0 || len(uncles) > 0 || !filter { err := pm.downloader.DeliverBodies(p.id, trasactions, uncles) if err != nil { - log.Debug(fmt.Sprint(err)) + log.Debug("Failed to deliver bodies", "err", err) } } @@ -555,7 +553,7 @@ func (pm *ProtocolManager) handleMsg(p *peer) error { } // Deliver all to the downloader if err := pm.downloader.DeliverNodeData(p.id, data); err != nil { - log.Debug(fmt.Sprintf("failed to deliver node state data: %v", err)) + log.Debug("Failed to deliver node state data", "err", err) } case p.version >= eth63 && msg.Code == GetReceiptsMsg: @@ -586,7 +584,7 @@ func (pm *ProtocolManager) handleMsg(p *peer) error { } // If known, encode and queue for response packet if encoded, err := rlp.EncodeToBytes(results); err != nil { - log.Error(fmt.Sprintf("failed to encode receipt: %v", err)) + log.Error("Failed to encode receipt", "err", err) } else { receipts = append(receipts, encoded) bytes += len(encoded) @@ -602,7 +600,7 @@ func (pm *ProtocolManager) handleMsg(p *peer) error { } // Deliver all to the downloader if err := pm.downloader.DeliverReceipts(p.id, receipts); err != nil { - log.Debug(fmt.Sprintf("failed to deliver receipts: %v", err)) + log.Debug("Failed to deliver receipts", "err", err) } case msg.Code == NewBlockHashesMsg: @@ -695,7 +693,7 @@ func (pm *ProtocolManager) BroadcastBlock(block *types.Block, propagate bool) { if parent := pm.blockchain.GetBlock(block.ParentHash(), block.NumberU64()-1); parent != nil { td = new(big.Int).Add(block.Difficulty(), pm.blockchain.GetTd(block.ParentHash(), block.NumberU64()-1)) } else { - log.Error(fmt.Sprintf("propagating dangling block #%d [%x]", block.NumberU64(), hash[:4])) + log.Error("Propagating dangling block", "number", block.Number(), "hash", hash) return } // Send the block to a subset of our peers @@ -703,14 +701,14 @@ func (pm *ProtocolManager) BroadcastBlock(block *types.Block, propagate bool) { for _, peer := range transfer { peer.SendNewBlock(block, td) } - log.Trace(fmt.Sprintf("propagated block %x to %d peers in %v", hash[:4], len(transfer), time.Since(block.ReceivedAt))) + log.Trace("Propagated block", "hash", hash, "recipients", len(transfer), "duration", common.PrettyDuration(time.Since(block.ReceivedAt))) } // Otherwise if the block is indeed in out own chain, announce it if pm.blockchain.HasBlock(hash) { for _, peer := range peers { peer.SendNewBlockHashes([]common.Hash{hash}, []uint64{block.NumberU64()}) } - log.Trace(fmt.Sprintf("announced block %x to %d peers in %v", hash[:4], len(peers), time.Since(block.ReceivedAt))) + log.Trace("Announced block", "hash", hash, "recipients", len(peers), "duration", common.PrettyDuration(time.Since(block.ReceivedAt))) } } @@ -723,7 +721,7 @@ func (pm *ProtocolManager) BroadcastTx(hash common.Hash, tx *types.Transaction) for _, peer := range peers { peer.SendTransactions(types.Transactions{tx}) } - log.Trace(fmt.Sprint("broadcast tx to", len(peers), "peers")) + log.Trace("Broadcast transaction", "hash", hash, "recipients", len(peers)) } // Mined broadcast loop -- cgit