various log fixes

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)
 	}
 }

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)
 		}
 	}
 

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)
 	}
 }
 

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
 	}
 

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.

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

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)
 			}

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()
 	}
 }

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:

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 {