p2p, p2p/discover, p2p/nat: rework logging using context keys

1 files changed, 25 insertions, 21 deletions

diff --git a/p2p/discover/udp.go b/p2p/discover/udp.go
index eafc3f394..93545e7d5 100644
--- a/p2p/discover/udp.go
+++ b/p2p/discover/udp.go
@@ -147,6 +147,7 @@ func nodeToRPC(n *Node) rpcNode {
 
 type packet interface {
 	handle(t *udp, from *net.UDPAddr, fromID NodeID, mac []byte) error
+	name() string
 }
 
 type conn interface {
@@ -223,7 +224,7 @@ func ListenUDP(priv *ecdsa.PrivateKey, laddr string, natm nat.Interface, nodeDBP
 	if err != nil {
 		return nil, err
 	}
-	log.Info(fmt.Sprint("Listening,", tab.self))
+	log.Debug("UDP listener up", "self", tab.self)
 	return tab, nil
 }
 
@@ -269,7 +270,7 @@ func (t *udp) close() {
 func (t *udp) ping(toid NodeID, toaddr *net.UDPAddr) error {
 	// TODO: maybe check for ReplyTo field in callback to measure RTT
 	errc := t.pending(toid, pongPacket, func(interface{}) bool { return true })
-	t.send(toaddr, pingPacket, ping{
+	t.send(toaddr, pingPacket, &ping{
 		Version:    Version,
 		From:       t.ourEndpoint,
 		To:         makeEndpoint(toaddr, 0), // TODO: maybe use known TCP port from DB
@@ -293,14 +294,14 @@ func (t *udp) findnode(toid NodeID, toaddr *net.UDPAddr, target NodeID) ([]*Node
 			nreceived++
 			n, err := t.nodeFromRPC(toaddr, rn)
 			if err != nil {
-				log.Trace(fmt.Sprintf("invalid neighbor node (%v) from %v: %v", rn.IP, toaddr, err))
+				log.Trace("Invalid neighbor node received", "ip", rn.IP, "addr", toaddr, "err", err)
 				continue
 			}
 			nodes = append(nodes, n)
 		}
 		return nreceived >= bucketSize
 	})
-	t.send(toaddr, findnodePacket, findnode{
+	t.send(toaddr, findnodePacket, &findnode{
 		Target:     target,
 		Expiration: uint64(time.Now().Add(expiration).Unix()),
 	})
@@ -458,15 +459,13 @@ func init() {
 	}
 }
 
-func (t *udp) send(toaddr *net.UDPAddr, ptype byte, req interface{}) error {
+func (t *udp) send(toaddr *net.UDPAddr, ptype byte, req packet) error {
 	packet, err := encodePacket(t.priv, ptype, req)
 	if err != nil {
 		return err
 	}
-	log.Trace(fmt.Sprintf(">>> %v %T", toaddr, req))
-	if _, err = t.conn.WriteToUDP(packet, toaddr); err != nil {
-		log.Trace(fmt.Sprint("UDP send failed:", err))
-	}
+	_, err = t.conn.WriteToUDP(packet, toaddr)
+	log.Trace(">> "+req.name(), "addr", toaddr, "err", err)
 	return err
 }
 
@@ -475,13 +474,13 @@ func encodePacket(priv *ecdsa.PrivateKey, ptype byte, req interface{}) ([]byte,
 	b.Write(headSpace)
 	b.WriteByte(ptype)
 	if err := rlp.Encode(b, req); err != nil {
-		log.Error(fmt.Sprint("error encoding packet:", err))
+		log.Error("Can't encode discv4 packet", "err", err)
 		return nil, err
 	}
 	packet := b.Bytes()
 	sig, err := crypto.Sign(crypto.Keccak256(packet[headSize:]), priv)
 	if err != nil {
-		log.Error(fmt.Sprint("could not sign packet:", err))
+		log.Error("Can't sign discv4 packet", "err", err)
 		return nil, err
 	}
 	copy(packet[macSize:], sig)
@@ -503,11 +502,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.Debug("Temporary UDP read error", "err", err)
 			continue
 		} else if err != nil {
 			// Shut down the loop for permament errors.
-			log.Debug(fmt.Sprintf("Read error: %v", err))
+			log.Debug("UDP read error", "err", err)
 			return
 		}
 		t.handlePacket(from, buf[:nbytes])
@@ -517,14 +516,11 @@ func (t *udp) readLoop() {
 func (t *udp) handlePacket(from *net.UDPAddr, buf []byte) error {
 	packet, fromID, hash, err := decodePacket(buf)
 	if err != nil {
-		log.Debug(fmt.Sprintf("Bad packet from %v: %v", from, err))
+		log.Debug("Bad discv4 packet", "addr", from, "err", err)
 		return err
 	}
-	status := "ok"
-	if err = packet.handle(t, from, fromID, hash); err != nil {
-		status = err.Error()
-	}
-	log.Trace(fmt.Sprintf("<<< %v %T: %s", from, packet, status))
+	err = packet.handle(t, from, fromID, hash)
+	log.Trace("<< "+packet.name(), "addr", from, "err", err)
 	return err
 }
 
@@ -563,7 +559,7 @@ func (req *ping) handle(t *udp, from *net.UDPAddr, fromID NodeID, mac []byte) er
 	if expired(req.Expiration) {
 		return errExpired
 	}
-	t.send(from, pongPacket, pong{
+	t.send(from, pongPacket, &pong{
 		To:         makeEndpoint(from, req.From.TCP),
 		ReplyTok:   mac,
 		Expiration: uint64(time.Now().Add(expiration).Unix()),
@@ -575,6 +571,8 @@ func (req *ping) handle(t *udp, from *net.UDPAddr, fromID NodeID, mac []byte) er
 	return nil
 }
 
+func (req *ping) name() string { return "PING/v4" }
+
 func (req *pong) handle(t *udp, from *net.UDPAddr, fromID NodeID, mac []byte) error {
 	if expired(req.Expiration) {
 		return errExpired
@@ -585,6 +583,8 @@ func (req *pong) handle(t *udp, from *net.UDPAddr, fromID NodeID, mac []byte) er
 	return nil
 }
 
+func (req *pong) name() string { return "PONG/v4" }
+
 func (req *findnode) handle(t *udp, from *net.UDPAddr, fromID NodeID, mac []byte) error {
 	if expired(req.Expiration) {
 		return errExpired
@@ -613,13 +613,15 @@ func (req *findnode) handle(t *udp, from *net.UDPAddr, fromID NodeID, mac []byte
 		}
 		p.Nodes = append(p.Nodes, nodeToRPC(n))
 		if len(p.Nodes) == maxNeighbors || i == len(closest)-1 {
-			t.send(from, neighborsPacket, p)
+			t.send(from, neighborsPacket, &p)
 			p.Nodes = p.Nodes[:0]
 		}
 	}
 	return nil
 }
 
+func (req *findnode) name() string { return "FINDNODE/v4" }
+
 func (req *neighbors) handle(t *udp, from *net.UDPAddr, fromID NodeID, mac []byte) error {
 	if expired(req.Expiration) {
 		return errExpired
@@ -630,6 +632,8 @@ func (req *neighbors) handle(t *udp, from *net.UDPAddr, fromID NodeID, mac []byt
 	return nil
 }
 
+func (req *neighbors) name() string { return "NEIGHBORS/v4" }
+
 func expired(ts uint64) bool {
 	return time.Unix(int64(ts), 0).Before(time.Now())
 }