Merge pull request #3433 from halseth/atpl-nodescore-tracelogs

[autopilot] Add trace logging during node scoring

autopilot/agent.go

@@ -523,6 +523,17 @@ func (a *Agent) controller() {
 func (a *Agent) openChans(availableFunds btcutil.Amount, numChans uint32,
 	totalChans []Channel) error {
 
+	// As channel size we'll use the maximum channel size available.
+	chanSize := a.cfg.Constraints.MaxChanSize()
+	if availableFunds < chanSize {
+		chanSize = availableFunds
+	}
+
+	if chanSize < a.cfg.Constraints.MinChanSize() {
+		return fmt.Errorf("not enough funds available to open a " +
+			"single channel")
+	}
+
 	// We're to attempt an attachment so we'll obtain the set of
 	// nodes that we currently have channels with so we avoid
 	// duplicate edges.
@@ -548,6 +559,7 @@ func (a *Agent) openChans(availableFunds btcutil.Amount, numChans uint32,
 		// order to avoid attempting to make a channel with
 		// ourselves.
 		if bytes.Equal(nID[:], selfPubBytes) {
+			log.Tracef("Skipping self node %x", nID[:])
 			return nil
 		}
 
@@ -555,6 +567,8 @@ func (a *Agent) openChans(availableFunds btcutil.Amount, numChans uint32,
 		// so we'll skip it.
 		addrs := node.Addrs()
 		if len(addrs) == 0 {
+			log.Tracef("Skipping node %x since no addresses known",
+				nID[:])
 			return nil
 		}
 		addresses[nID] = addrs
@@ -562,6 +576,7 @@ func (a *Agent) openChans(availableFunds btcutil.Amount, numChans uint32,
 		// Additionally, if this node is in the blacklist, then
 		// we'll skip it.
 		if _, ok := nodesToSkip[nID]; ok {
+			log.Tracef("Skipping blacklisted node %x", nID[:])
 			return nil
 		}
 
@@ -571,17 +586,6 @@ func (a *Agent) openChans(availableFunds btcutil.Amount, numChans uint32,
 		return fmt.Errorf("unable to get graph nodes: %v", err)
 	}
 
-	// As channel size we'll use the maximum channel size available.
-	chanSize := a.cfg.Constraints.MaxChanSize()
-	if availableFunds < chanSize {
-		chanSize = availableFunds
-	}
-
-	if chanSize < a.cfg.Constraints.MinChanSize() {
-		return fmt.Errorf("not enough funds available to open a " +
-			"single channel")
-	}
-
 	// Use the heuristic to calculate a score for each node in the
 	// graph.
 	log.Debugf("Scoring %d nodes for chan_size=%v", len(nodes), chanSize)
@@ -604,12 +608,17 @@ func (a *Agent) openChans(availableFunds btcutil.Amount, numChans uint32,
 
 	chanCandidates := make(map[NodeID]*AttachmentDirective)
 	for nID := range scores {
+		log.Tracef("Creating attachment directive for chosen node %x",
+			nID[:])
+
 		// Add addresses to the candidates.
 		addrs := addresses[nID]
 
 		// If the node has no known addresses, we cannot connect to it,
 		// so we'll skip it.
 		if len(addrs) == 0 {
+			log.Tracef("Skipping scored node %x with no addresses",
+				nID[:])
 			continue
 		}
 
@@ -621,6 +630,9 @@ func (a *Agent) openChans(availableFunds btcutil.Amount, numChans uint32,
 
 		// If we run out of funds, we can break early.
 		if chanSize < a.cfg.Constraints.MinChanSize() {
+			log.Tracef("Chan size %v too small to satisfy min "+
+				"channel size %v, breaking", chanSize,
+				a.cfg.Constraints.MinChanSize())
 			break
 		}
 

autopilot/combinedattach.go

@@ -78,6 +78,8 @@ func (c *WeightedCombAttachment) NodeScores(g ChannelGraph, chans []Channel,
 	// nodes for the given channel size.
 	var subScores []map[NodeID]*NodeScore
 	for _, h := range c.heuristics {
+		log.Tracef("Getting scores from sub heuristic %v", h.Name())
+
 		s, err := h.NodeScores(
 			g, chans, chanSize, nodes,
 		)
@@ -102,14 +104,24 @@ func (c *WeightedCombAttachment) NodeScores(g ChannelGraph, chans []Channel,
 		for i, h := range c.heuristics {
 			sub, ok := subScores[i][nID]
 			if !ok {
+				log.Tracef("No score given to node %x by sub "+
+					"heuristic %v", nID[:], h.Name())
 				continue
 			}
 			// Use the heuristic's weight factor to determine of
 			// how much weight we should give to this particular
 			// score.
-			score.Score += h.Weight * sub.Score
+			subScore := h.Weight * sub.Score
+			log.Tracef("Giving node %x a sub score of %v "+
+				"(%v * %v) from sub heuristic %v", nID[:],
+				subScore, h.Weight, sub.Score, h.Name())
+
+			score.Score += subScore
 		}
 
+		log.Tracef("Node %x got final combined score %v", nID[:],
+			score.Score)
+
 		switch {
 		// Instead of adding a node with score 0 to the returned set,
 		// we just skip it.

autopilot/externalscoreattach.go

@@ -62,6 +62,8 @@ func (s *ExternalScoreAttachment) SetNodeScores(targetHeuristic string,
 	defer s.Unlock()
 
 	s.nodeScores = newScores
+	log.Tracef("Setting %v external scores", len(s.nodeScores))
+
 	return true, nil
 }
 
@@ -90,25 +92,30 @@ func (s *ExternalScoreAttachment) NodeScores(g ChannelGraph, chans []Channel,
 	s.Lock()
 	defer s.Unlock()
 
+	log.Tracef("External scoring %v nodes, from %v set scores",
+		len(nodes), len(s.nodeScores))
+
 	// Fill the map of candidates to return.
 	candidates := make(map[NodeID]*NodeScore)
 	for nID := range nodes {
 		var score float64
 		if nodeScore, ok := s.nodeScores[nID]; ok {
-			score = float64(nodeScore)
+			score = nodeScore
 		}
 
-		_, ok := existingPeers[nID]
-		switch {
-
 		// If the node is among or existing channel peers, we don't
 		// need another channel.
-		case ok:
+		if _, ok := existingPeers[nID]; ok {
+			log.Tracef("Skipping existing peer %x from external "+
+				"score results", nID[:])
 			continue
+		}
+
+		log.Tracef("External score %v given to node %x", score, nID[:])
 
 		// Instead of adding a node with score 0 to the returned set,
 		// we just skip it.
-		case score == 0:
+		if score == 0 {
 			continue
 		}
 

autopilot/prefattach.go

@@ -107,6 +107,8 @@ func (p *PrefAttachment) NodeScores(g ChannelGraph, chans []Channel,
 	}
 
 	medianChanSize := Median(allChans)
+	log.Tracef("Found channel median %v for preferential score heuristic",
+		medianChanSize)
 
 	// Count the number of large-ish channels for each particular node in
 	// the graph.
@@ -143,11 +145,14 @@ func (p *PrefAttachment) NodeScores(g ChannelGraph, chans []Channel,
 		// early.
 		nID := NodeID(n.PubKey())
 		if _, ok := nodes[nID]; !ok {
+			log.Tracef("Node %x not among nodes to score, "+
+				"ignoring", nID[:])
 			return nil
 		}
 
 		// Otherwise we'll record the number of channels.
 		nodeChanNum[nID] = nodeChans
+		log.Tracef("Counted %v channels for node %x", nodeChans, nID[:])
 
 		return nil
 	}); err != nil {
@@ -158,6 +163,7 @@ func (p *PrefAttachment) NodeScores(g ChannelGraph, chans []Channel,
 	// preferences, so we return, indicating all candidates get a score of
 	// zero.
 	if maxChans == 0 {
+		log.Tracef("No channels in the graph")
 		return nil, nil
 	}
 
@@ -171,18 +177,19 @@ func (p *PrefAttachment) NodeScores(g ChannelGraph, chans []Channel,
 	candidates := make(map[NodeID]*NodeScore)
 	for nID, nodeChans := range nodeChanNum {
 
-		_, ok := existingPeers[nID]
-
-		switch {
-
 		// If the node is among or existing channel peers, we don't
 		// need another channel.
-		case ok:
+		if _, ok := existingPeers[nID]; ok {
+			log.Tracef("Node %x among existing peers for pref "+
+				"attach heuristic, giving zero score", nID[:])
 			continue
+		}
 
 		// If the node had no large channels, we skip it, since it
 		// would have gotten a zero score anyway.
-		case nodeChans <= 0:
+		if nodeChans <= 0 {
+			log.Tracef("Skipping node %x with channel count %v",
+				nID[:], nodeChans)
 			continue
 		}
 
@@ -190,6 +197,9 @@ func (p *PrefAttachment) NodeScores(g ChannelGraph, chans []Channel,
 		// channels in the graph, scaled such that the highest-degree
 		// node will be given a score of 1.0.
 		score := float64(nodeChans) / float64(maxChans)
+		log.Tracef("Giving node %x a pref attach score of %v",
+			nID[:], score)
+
 		candidates[nID] = &NodeScore{
 			NodeID: nID,
 			Score:  score,