p2p/discv5: fix reg lookup, polish code, use logger (#15737)

p2p/discv5/net.go

@@ -51,16 +51,9 @@ const (
 const testTopic = "foo"
 
 const (
-	printDebugLogs   = false
 	printTestImgLogs = false
 )
 
-func debugLog(s string) {
-	if printDebugLogs {
-		fmt.Println(s)
-	}
-}
-
 // Network manages the table and all protocol interaction.
 type Network struct {
 	db          *nodeDB // database of known nodes
@@ -388,14 +381,14 @@ func (net *Network) loop() {
 		}
 	}()
 	resetNextTicket := func() {
-		t, timeout := net.ticketStore.nextFilteredTicket()
-		if t != nextTicket {
-			nextTicket = t
+		ticket, timeout := net.ticketStore.nextFilteredTicket()
+		if nextTicket != ticket {
+			nextTicket = ticket
 			if nextRegisterTimer != nil {
 				nextRegisterTimer.Stop()
 				nextRegisterTime = nil
 			}
-			if t != nil {
+			if ticket != nil {
 				nextRegisterTimer = time.NewTimer(timeout)
 				nextRegisterTime = nextRegisterTimer.C
 			}
@@ -423,13 +416,13 @@ loop:
 
 		select {
 		case <-net.closeReq:
-			debugLog("<-net.closeReq")
+			log.Trace("<-net.closeReq")
 			break loop
 
 		// Ingress packet handling.
 		case pkt := <-net.read:
 			//fmt.Println("read", pkt.ev)
-			debugLog("<-net.read")
+			log.Trace("<-net.read")
 			n := net.internNode(&pkt)
 			prestate := n.state
 			status := "ok"
@@ -444,7 +437,7 @@ loop:
 
 		// State transition timeouts.
 		case timeout := <-net.timeout:
-			debugLog("<-net.timeout")
+			log.Trace("<-net.timeout")
 			if net.timeoutTimers[timeout] == nil {
 				// Stale timer (was aborted).
 				continue
@@ -462,20 +455,20 @@ loop:
 
 		// Querying.
 		case q := <-net.queryReq:
-			debugLog("<-net.queryReq")
+			log.Trace("<-net.queryReq")
 			if !q.start(net) {
 				q.remote.deferQuery(q)
 			}
 
 		// Interacting with the table.
 		case f := <-net.tableOpReq:
-			debugLog("<-net.tableOpReq")
+			log.Trace("<-net.tableOpReq")
 			f()
 			net.tableOpResp <- struct{}{}
 
 		// Topic registration stuff.
 		case req := <-net.topicRegisterReq:
-			debugLog("<-net.topicRegisterReq")
+			log.Trace("<-net.topicRegisterReq")
 			if !req.add {
 				net.ticketStore.removeRegisterTopic(req.topic)
 				continue
@@ -486,7 +479,7 @@ loop:
 			// determination for new topics.
 			// if topicRegisterLookupDone == nil {
 			if topicRegisterLookupTarget.target == (common.Hash{}) {
-				debugLog("topicRegisterLookupTarget == null")
+				log.Trace("topicRegisterLookupTarget == null")
 				if topicRegisterLookupTick.Stop() {
 					<-topicRegisterLookupTick.C
 				}
@@ -496,7 +489,7 @@ loop:
 			}
 
 		case nodes := <-topicRegisterLookupDone:
-			debugLog("<-topicRegisterLookupDone")
+			log.Trace("<-topicRegisterLookupDone")
 			net.ticketStore.registerLookupDone(topicRegisterLookupTarget, nodes, func(n *Node) []byte {
 				net.ping(n, n.addr())
 				return n.pingEcho
@@ -507,7 +500,7 @@ loop:
 			topicRegisterLookupDone = nil
 
 		case <-topicRegisterLookupTick.C:
-			debugLog("<-topicRegisterLookupTick")
+			log.Trace("<-topicRegisterLookupTick")
 			if (topicRegisterLookupTarget.target == common.Hash{}) {
 				target, delay := net.ticketStore.nextRegisterLookup()
 				topicRegisterLookupTarget = target
@@ -520,14 +513,14 @@ loop:
 			}
 
 		case <-nextRegisterTime:
-			debugLog("<-nextRegisterTime")
+			log.Trace("<-nextRegisterTime")
 			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 {
-				debugLog("<-net.topicSearchReq")
+				log.Trace("<-net.topicSearchReq")
 				info, ok := searchInfo[req.topic]
 				if ok {
 					if req.delay == time.Duration(0) {
@@ -588,7 +581,7 @@ loop:
 			})
 
 		case <-statsDump.C:
-			debugLog("<-statsDump.C")
+			log.Trace("<-statsDump.C")
 			/*r, ok := net.ticketStore.radius[testTopic]
 			if !ok {
 				fmt.Printf("(%x) no radius @ %v\n", net.tab.self.ID[:8], time.Now())
@@ -617,7 +610,7 @@ loop:
 
 		// Periodic / lookup-initiated bucket refresh.
 		case <-refreshTimer.C:
-			debugLog("<-refreshTimer.C")
+			log.Trace("<-refreshTimer.C")
 			// TODO: ideally we would start the refresh timer after
 			// fallback nodes have been set for the first time.
 			if refreshDone == nil {
@@ -631,7 +624,7 @@ loop:
 				bucketRefreshTimer.Reset(bucketRefreshInterval)
 			}()
 		case newNursery := <-net.refreshReq:
-			debugLog("<-net.refreshReq")
+			log.Trace("<-net.refreshReq")
 			if newNursery != nil {
 				net.nursery = newNursery
 			}
@@ -641,7 +634,7 @@ loop:
 			}
 			net.refreshResp <- refreshDone
 		case <-refreshDone:
-			debugLog("<-net.refreshDone")
+			log.Trace("<-net.refreshDone")
 			refreshDone = nil
 			list := searchReqWhenRefreshDone
 			searchReqWhenRefreshDone = nil
@@ -652,7 +645,7 @@ loop:
 			}()
 		}
 	}
-	debugLog("loop stopped")
+	log.Trace("loop stopped")
 
 	log.Debug(fmt.Sprintf("shutting down"))
 	if net.conn != nil {
@@ -1109,14 +1102,14 @@ func (net *Network) ping(n *Node, addr *net.UDPAddr) {
 		//fmt.Println(" not sent")
 		return
 	}
-	debugLog(fmt.Sprintf("ping(node = %x)", n.ID[:8]))
+	log.Trace("Pinging remote node", "node", n.ID)
 	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) {
-	debugLog(fmt.Sprintf("handlePing(node = %x)", n.ID[:8]))
+	log.Trace("Handling remote ping", "node", n.ID)
 	ping := pkt.data.(*ping)
 	n.TCP = ping.From.TCP
 	t := net.topictab.getTicket(n, ping.Topics)
@@ -1131,7 +1124,7 @@ func (net *Network) handlePing(n *Node, pkt *ingressPacket) {
 }
 
 func (net *Network) handleKnownPong(n *Node, pkt *ingressPacket) error {
-	debugLog(fmt.Sprintf("handleKnownPong(node = %x)", n.ID[:8]))
+	log.Trace("Handling known pong", "node", n.ID)
 	net.abortTimedEvent(n, pongTimeout)
 	now := mclock.Now()
 	ticket, err := pongToTicket(now, n.pingTopics, n, pkt)
@@ -1139,9 +1132,8 @@ 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 {
-		debugLog(fmt.Sprintf(" error: %v", err))
+		log.Trace("Failed to convert pong to ticket", "err", err)
 	}
-
 	n.pingEcho = nil
 	n.pingTopics = nil
 	return err

p2p/discv5/node.go

@@ -273,6 +273,11 @@ func (n NodeID) GoString() string {
 	return fmt.Sprintf("discover.HexID(\"%x\")", n[:])
 }
 
+// TerminalString returns a shortened hex string for terminal logging.
+func (n NodeID) TerminalString() string {
+	return hex.EncodeToString(n[:8])
+}
+
 // HexID converts a hex string to a NodeID.
 // The string may be prefixed with 0x.
 func HexID(in string) (NodeID, error) {

p2p/discv5/topic.go

@@ -24,6 +24,7 @@ import (
 	"time"
 
 	"github.com/ethereum/go-ethereum/common/mclock"
+	"github.com/ethereum/go-ethereum/log"
 )
 
 const (
@@ -235,7 +236,7 @@ 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) {
-	debugLog(fmt.Sprintf("useTicket %v %v %v", serialNo, topics, waitPeriods))
+	log.Trace("Using discovery ticket", "serial", serialNo, "topics", topics, "waits", waitPeriods)
 	//fmt.Println("useTicket", serialNo, topics, waitPeriods)
 	t.collectGarbage()