From 07b5b7a8f2517e459422bed3ee472cb3a905ed85 Mon Sep 17 00:00:00 2001 From: Jae Kwon Date: Mon, 29 Dec 2014 18:39:19 -0800 Subject: [PATCH] various log fixes --- alert/alert.go | 10 ++++------ cmd/daemon.go | 6 +++--- consensus/reactor.go | 6 +++--- consensus/state.go | 6 +++--- mempool/reactor.go | 9 ++++----- p2p/addrbook.go | 11 +++++------ p2p/connection.go | 38 +++++++++++++++++++------------------- p2p/peer.go | 4 ++-- p2p/pex_reactor.go | 4 ++-- p2p/switch.go | 7 +++---- 10 files changed, 48 insertions(+), 53 deletions(-) diff --git a/alert/alert.go b/alert/alert.go index d4e847665..64e6c3830 100644 --- a/alert/alert.go +++ b/alert/alert.go @@ -5,8 +5,6 @@ import ( "time" "github.com/sfreiberg/gotwilio" - - . "github.com/tendermint/tendermint/common" . "github.com/tendermint/tendermint/config" ) @@ -37,7 +35,7 @@ func Alert(message string) { func sendTwilio(message string) { defer func() { if err := recover(); err != nil { - log.Error(Fmt("sendTwilio error: %v", err)) + log.Error("sendTwilio error", "error", err) } }() if len(message) > 50 { @@ -46,14 +44,14 @@ func sendTwilio(message string) { twilio := gotwilio.NewTwilioClient(Config.Alert.TwilioSid, Config.Alert.TwilioToken) res, exp, err := twilio.SendSMS(Config.Alert.TwilioFrom, Config.Alert.TwilioTo, message, "", "") if exp != nil || err != nil { - log.Error(Fmt("sendTwilio error: %v %v %v", res, exp, err)) + log.Error("sendTwilio error", "res", res, "exp", exp, "error", err) } } func sendEmail(message string) { defer func() { if err := recover(); err != nil { - log.Error(Fmt("sendEmail error: %v", err)) + log.Error("sendEmail error", "error", err) } }() subject := message @@ -62,6 +60,6 @@ func sendEmail(message string) { } err := SendEmail(subject, message, Config.Alert.EmailRecipients) if err != nil { - log.Error(Fmt("sendEmail error: %v\n%v", err, message)) + log.Error("sendEmail error", "error", err, "message", message) } } diff --git a/cmd/daemon.go b/cmd/daemon.go index a0725a3eb..f8d45003a 100644 --- a/cmd/daemon.go +++ b/cmd/daemon.go @@ -5,8 +5,8 @@ import ( "os/signal" "github.com/tendermint/tendermint/block" - "github.com/tendermint/tendermint/config" . "github.com/tendermint/tendermint/common" + "github.com/tendermint/tendermint/config" "github.com/tendermint/tendermint/consensus" db_ "github.com/tendermint/tendermint/db" mempool_ "github.com/tendermint/tendermint/mempool" @@ -126,11 +126,11 @@ func daemon() { if config.Config.SeedNode != "" { peer, err := n.sw.DialPeerWithAddress(p2p.NewNetAddressString(config.Config.SeedNode)) if err != nil { - log.Error(Fmt("Error dialing seed: %v", err)) + log.Error("Error dialing seed", "error", err) //n.book.MarkAttempt(addr) return } else { - log.Info(Fmt("Connected to seed: %v", peer)) + log.Info("Connected to seed", "peer", peer) } } diff --git a/consensus/reactor.go b/consensus/reactor.go index 176b6bbaa..11b1c3ae9 100644 --- a/consensus/reactor.go +++ b/consensus/reactor.go @@ -116,7 +116,7 @@ func (conR *ConsensusReactor) Receive(chId byte, peer *p2p.Peer, msgBytes []byte log.Warn("Error decoding message", "channel", chId, "peer", peer, "msg", msg_, "error", err, "bytes", msgBytes) return } - log.Debug("RECEIVE", "channel", chId, "peer", peer, "msg", msg_, "bytes", msgBytes) + log.Debug("Receive", "channel", chId, "peer", peer, "msg", msg_, "bytes", msgBytes) switch chId { case StateCh: @@ -173,7 +173,7 @@ func (conR *ConsensusReactor) Receive(chId byte, peer *p2p.Peer, msgBytes []byte added, index, err := conR.conS.AddVote(address, vote) if err != nil { // Probably an invalid signature. Bad peer. - log.Warn(Fmt("Error attempting to add vote: %v", err)) + log.Warn("Error attempting to add vote", "error", err) } // Initialize Prevotes/Precommits/Commits if needed ps.EnsureVoteBitArrays(rs.Height, rs.Validators.Size()) @@ -196,7 +196,7 @@ func (conR *ConsensusReactor) Receive(chId byte, peer *p2p.Peer, msgBytes []byte } if err != nil { - log.Warn(Fmt("Error in Receive(): %v", err)) + log.Warn("Error in Receive()", "error", err) } } diff --git a/consensus/state.go b/consensus/state.go index 7c3a20efa..2bd975451 100644 --- a/consensus/state.go +++ b/consensus/state.go @@ -610,7 +610,7 @@ func (cs *ConsensusState) RunActionPrevote(height uint, round uint) { err := cs.stageBlock(cs.ProposalBlock, cs.ProposalBlockParts) if err != nil { // ProposalBlock is invalid, prevote nil. - log.Warn(Fmt("ProposalBlock is invalid: %v", err)) + log.Warn("ProposalBlock is invalid", "error", err) cs.signAddVote(VoteTypePrevote, nil, PartSetHeader{}) return } @@ -661,7 +661,7 @@ func (cs *ConsensusState) RunActionPrecommit(height uint, round uint) { // Validate the block. if err := cs.stageBlock(cs.ProposalBlock, cs.ProposalBlockParts); err != nil { // Prevent zombies. - log.Warn(Fmt("+2/3 prevoted for an invalid block: %v", err)) + log.Warn("+2/3 prevoted for an invalid block", "error", err) return } cs.LockedBlock = cs.ProposalBlock @@ -974,7 +974,7 @@ func (cs *ConsensusState) saveCommitVoteBlock(block *Block, blockParts *PartSet) // The proposal must be valid. if err := cs.stageBlock(block, blockParts); err != nil { // Prevent zombies. - log.Warn(Fmt("+2/3 precommitted an invalid block: %v", err)) + log.Warn("+2/3 precommitted an invalid block", "error", err) return } diff --git a/mempool/reactor.go b/mempool/reactor.go index f46185c7a..c380a44c1 100644 --- a/mempool/reactor.go +++ b/mempool/reactor.go @@ -7,7 +7,6 @@ import ( . "github.com/tendermint/tendermint/binary" . "github.com/tendermint/tendermint/block" - . "github.com/tendermint/tendermint/common" "github.com/tendermint/tendermint/p2p" ) @@ -71,10 +70,10 @@ func (pexR *MempoolReactor) RemovePeer(peer *p2p.Peer, reason interface{}) { func (memR *MempoolReactor) Receive(chId byte, src *p2p.Peer, msgBytes []byte) { _, msg_, err := DecodeMessage(msgBytes) if err != nil { - log.Warn(Fmt("Error decoding message: %v", err)) + log.Warn("Error decoding message", "error", err) return } - log.Info(Fmt("MempoolReactor received %v", msg_)) + log.Info("MempoolReactor received message", "msg", msg_) switch msg_.(type) { case *TxMessage: @@ -82,10 +81,10 @@ func (memR *MempoolReactor) Receive(chId byte, src *p2p.Peer, msgBytes []byte) { err := memR.Mempool.AddTx(msg.Tx) if err != nil { // Bad, seen, or conflicting tx. - log.Debug(Fmt("Could not add tx %v", msg.Tx)) + log.Debug("Could not add tx", "tx", msg.Tx) return } else { - log.Debug(Fmt("Added valid tx %V", msg.Tx)) + log.Debug("Added valid tx", "tx", msg.Tx) } // Share tx. // We use a simple shotgun approach for now. diff --git a/p2p/addrbook.go b/p2p/addrbook.go index 8154b6ffa..dcb41d82f 100644 --- a/p2p/addrbook.go +++ b/p2p/addrbook.go @@ -7,7 +7,6 @@ package p2p import ( "encoding/binary" "encoding/json" - "fmt" "math" "math/rand" "net" @@ -320,14 +319,14 @@ func (a *AddrBook) saveToFile(filePath string) { w, err := os.Create(filePath) if err != nil { - log.Error("Error opening file: ", filePath, err) + log.Error("Error opening file", "file", filePath, "error", err) return } defer w.Close() jsonBytes, err := json.MarshalIndent(aJSON, "", "\t") _, err = w.Write(jsonBytes) if err != nil { - log.Error(Fmt("Failed to save AddrBook to file %v: %v", filePath, err)) + log.Error("Failed to save AddrBook to file", "file", filePath, "error", err) } } @@ -341,14 +340,14 @@ func (a *AddrBook) loadFromFile(filePath string) { // Load addrBookJSON{} r, err := os.Open(filePath) if err != nil { - panic(fmt.Errorf("Error opening file %s: %v", filePath, err)) + panic(Fmt("Error opening file %s: %v", filePath, err)) } defer r.Close() aJSON := &addrBookJSON{} dec := json.NewDecoder(r) err = dec.Decode(aJSON) if err != nil { - panic(fmt.Errorf("Error reading file %s: %v", filePath, err)) + panic(Fmt("Error reading file %s: %v", filePath, err)) } // Restore all the fields... @@ -377,7 +376,7 @@ out: for { select { case <-dumpAddressTicker.C: - log.Debug(Fmt("Saving book to file (%v)", a.Size())) + log.Debug("Saving book to file", "size", a.Size()) a.saveToFile(a.filePath) case <-a.quit: break out diff --git a/p2p/connection.go b/p2p/connection.go index 20ee154fc..2b3a4a15c 100644 --- a/p2p/connection.go +++ b/p2p/connection.go @@ -123,7 +123,7 @@ func NewMConnection(conn net.Conn, chDescs []*ChannelDescriptor, onReceive recei // .Start() begins multiplexing packets to and from "channels". func (c *MConnection) Start() { if atomic.CompareAndSwapUint32(&c.started, 0, 1) { - log.Debug(Fmt("Starting %v", c)) + log.Debug("Starting MConnection", "connection", c) go c.sendRoutine() go c.recvRoutine() } @@ -131,7 +131,7 @@ func (c *MConnection) Start() { func (c *MConnection) Stop() { if atomic.CompareAndSwapUint32(&c.stopped, 0, 1) { - log.Debug(Fmt("Stopping %v", c)) + log.Debug("Stopping MConnection", "connection", c) close(c.quit) c.conn.Close() c.flushTimer.Stop() @@ -153,7 +153,7 @@ func (c *MConnection) flush() { err := c.bufWriter.Flush() if err != nil { if atomic.LoadUint32(&c.stopped) != 1 { - log.Warn(Fmt("MConnection flush failed: %v", err)) + log.Warn("MConnection flush failed", "error", err) } } } @@ -209,7 +209,7 @@ func (c *MConnection) TrySend(chId byte, msg interface{}) bool { return false } - log.Debug(Fmt("[%X] TRYSEND %v: %v", chId, c.RemoteAddress, msg)) + log.Debug("TrySend", "channel", chId, "connection", c, "msg", msg) // Send message to channel. channel, ok := c.channelsIdx[chId] @@ -286,7 +286,7 @@ FOR_LOOP: break FOR_LOOP } if err != nil { - log.Warn(Fmt("%v failed @ sendRoutine:\n%v", c, err)) + log.Warn("Connection failed @ sendRoutine", "connection", c, "error", err) c.Stop() break FOR_LOOP } @@ -341,7 +341,7 @@ func (c *MConnection) sendMsgPacket() bool { // Make & send a msgPacket from this channel n, err := leastChannel.writeMsgPacketTo(c.bufWriter) if err != nil { - log.Warn(Fmt("Failed to write msgPacket. Error: %v", err)) + log.Warn("Failed to write msgPacket", "error", err) c.stopForError(err) return true } @@ -361,6 +361,18 @@ FOR_LOOP: // Block until .recvMonitor says we can read. c.recvMonitor.Limit(maxMsgPacketSize, atomic.LoadInt64(&c.recvRate), true) + // Peek into bufReader for debugging + log.Debug("Peek connection buffer", "bytes", log15.Lazy{func() []byte { + numBytes := c.bufReader.Buffered() + bytes, err := c.bufReader.Peek(MinInt(numBytes, 100)) + if err == nil { + return bytes + } else { + log.Warn("Error peeking connection buffer", "error", err) + return nil + } + }}) + // Read packet type var n int64 var err error @@ -368,23 +380,12 @@ FOR_LOOP: c.recvMonitor.Update(int(n)) if err != nil { if atomic.LoadUint32(&c.stopped) != 1 { - log.Warn(Fmt("%v failed @ recvRoutine with err: %v", c, err)) + log.Warn("Connection failed @ recvRoutine", "connection", c, "error", err) c.Stop() } break FOR_LOOP } - // Peek into bufReader for debugging - log.Debug("%v", log15.Lazy{func() string { - numBytes := c.bufReader.Buffered() - bytes, err := c.bufReader.Peek(MinInt(numBytes, 100)) - if err == nil { - return fmt.Sprintf("recvRoutine packet type %X, peeked: %X", pktType, bytes) - } else { - return fmt.Sprintf("recvRoutine error: %v", err) - } - }}) - // Read more depending on packet type. switch pktType { case packetTypePing: @@ -408,7 +409,6 @@ FOR_LOOP: panic(Fmt("Unknown channel %X", pkt.ChannelId)) } msgBytes := channel.recvMsgPacket(pkt) - log.Warn(Fmt("RECEIVE_MSG_BYTES: %X", msgBytes)) if msgBytes != nil { c.onReceive(pkt.ChannelId, msgBytes) } diff --git a/p2p/peer.go b/p2p/peer.go index a6921bc91..ae5f7f537 100644 --- a/p2p/peer.go +++ b/p2p/peer.go @@ -46,14 +46,14 @@ func newPeer(conn net.Conn, outbound bool, reactorsByCh map[byte]Reactor, chDesc func (p *Peer) start() { if atomic.CompareAndSwapUint32(&p.started, 0, 1) { - log.Debug(Fmt("Starting %v", p)) + log.Debug("Starting Peer", "peer", p) p.mconn.Start() } } func (p *Peer) stop() { if atomic.CompareAndSwapUint32(&p.stopped, 0, 1) { - log.Debug(Fmt("Stopping %v", p)) + log.Debug("Stopping Peer", "peer", p) p.mconn.Stop() } } diff --git a/p2p/pex_reactor.go b/p2p/pex_reactor.go index dbc9536a2..3c28f8b68 100644 --- a/p2p/pex_reactor.go +++ b/p2p/pex_reactor.go @@ -90,10 +90,10 @@ func (pexR *PEXReactor) Receive(chId byte, src *Peer, msgBytes []byte) { // decode message msg, err := DecodeMessage(msgBytes) if err != nil { - log.Warn(Fmt("Error decoding message: %v", err)) + log.Warn("Error decoding message", "error", err) return } - log.Info(Fmt("requestRoutine received %v", msg)) + log.Info("Received message", "msg", msg) switch msg.(type) { case *pexRequestMessage: diff --git a/p2p/switch.go b/p2p/switch.go index 2a69dcab4..4f68108e9 100644 --- a/p2p/switch.go +++ b/p2p/switch.go @@ -117,9 +117,9 @@ func (sw *Switch) AddPeerWithConnection(conn net.Conn, outbound bool) (*Peer, er // Add the peer to .peers if sw.peers.Add(peer) { - log.Info(Fmt("+ %v", peer)) + log.Info("Added peer", "peer", peer) } else { - log.Info(Fmt("Ignoring duplicate: %v", peer)) + log.Info("Ignoring duplicate peer", "peer", peer) return nil, ErrSwitchDuplicatePeer } @@ -137,7 +137,7 @@ func (sw *Switch) DialPeerWithAddress(addr *NetAddress) (*Peer, error) { return nil, ErrSwitchStopped } - log.Info(Fmt("Dialing peer @ %v", addr)) + log.Info("Dialing peer", "address", addr) sw.dialing.Set(addr.String(), addr) conn, err := addr.DialTimeout(peerDialTimeoutSeconds * time.Second) sw.dialing.Delete(addr.String()) @@ -166,7 +166,6 @@ func (sw *Switch) Broadcast(chId byte, msg interface{}) (numSuccess, numFailure // XXX XXX Change. // success := peer.TrySend(chId, msg) success := peer.Send(chId, msg) - log.Debug(Fmt("[%X] for peer %v success: %v", chId, peer, success)) if success { numSuccess += 1 } else {