add some additional debug timing info and logging to dials, and fix an unnecessary delay in search startup

src/yggdrasil/dialer.go

@@ -65,12 +65,15 @@ func (d *Dialer) DialContext(ctx context.Context, network, address string) (net.
 // DialByNodeIDandMask opens a session to the given node based on raw
 // NodeID parameters. If ctx is nil or has no timeout, then a default timeout of 6 seconds will apply, beginning *after* the search finishes.
 func (d *Dialer) DialByNodeIDandMask(ctx context.Context, nodeID, nodeMask *crypto.NodeID) (net.Conn, error) {
+	startDial := time.Now()
 	conn := newConn(d.core, nodeID, nodeMask, nil)
 	if err := conn.search(); err != nil {
 		// TODO: make searches take a context, so they can be cancelled early
 		conn.Close()
 		return nil, err
 	}
+	endSearch := time.Now()
+	d.core.log.Debugln("Dial searched for:", nodeID, "in time:", endSearch.Sub(startDial))
 	conn.session.setConn(nil, conn)
 	var cancel context.CancelFunc
 	if ctx == nil {
@@ -80,6 +83,9 @@ func (d *Dialer) DialByNodeIDandMask(ctx context.Context, nodeID, nodeMask *cryp
 	defer cancel()
 	select {
 	case <-conn.session.init:
+		endInit := time.Now()
+		d.core.log.Debugln("Dial initialized session for:", nodeID, "in time:", endInit.Sub(endSearch))
+		d.core.log.Debugln("Finished dial for:", nodeID, "in time:", endInit.Sub(startDial))
 		return conn, nil
 	case <-ctx.Done():
 		conn.Close()

src/yggdrasil/search.go

@@ -22,9 +22,6 @@ import (
 	"github.com/yggdrasil-network/yggdrasil-go/src/crypto"
 )
 
-// This defines the maximum number of dhtInfo that we keep track of for nodes to query in an ongoing search.
-const search_MAX_SEARCH_SIZE = 16
-
 // This defines the time after which we time out a search (so it can restart).
 const search_RETRY_TIME = 3 * time.Second
 const search_STEP_TIME = 100 * time.Millisecond
@@ -79,7 +76,7 @@ func (s *searches) createSearch(dest *crypto.NodeID, mask *crypto.NodeID, callba
 // If there is, it adds the response info to the search and triggers a new search step.
 // If there's no ongoing search, or we if the dhtRes finished the search (it was from the target node), then don't do anything more.
 func (sinfo *searchInfo) handleDHTRes(res *dhtRes) {
-	old := sinfo.visited
+	var doStep bool
 	if res != nil {
 		sinfo.recv++
 		if sinfo.checkDHTRes(res) {
@@ -87,8 +84,13 @@ func (sinfo *searchInfo) handleDHTRes(res *dhtRes) {
 		}
 		// Add results to the search
 		sinfo.addToSearch(res)
+		// FIXME check this elsewhere so we don't need to create a from struct
+		from := dhtInfo{key: res.Key, coords: res.Coords}
+		doStep = sinfo.visited == *from.getNodeID()
+	} else {
+		doStep = true
 	}
-	if res == nil || sinfo.visited != old {
+	if doStep {
 		// Continue the search
 		sinfo.doSearchStep()
 	}
@@ -186,7 +188,7 @@ func (sinfo *searchInfo) checkDHTRes(res *dhtRes) bool {
 	from := dhtInfo{key: res.Key, coords: res.Coords}
 	if *from.getNodeID() != sinfo.visited && dht_ordered(&sinfo.dest, from.getNodeID(), &sinfo.visited) {
 		// Closer to the destination, so update visited
-		sinfo.searches.router.core.log.Debugln("Updating search:", sinfo.dest, *from.getNodeID(), sinfo.send, sinfo.recv)
+		sinfo.searches.router.core.log.Debugln("Updating search:", &sinfo.dest, from.getNodeID(), sinfo.send, sinfo.recv)
 		sinfo.visited = *from.getNodeID()
 		sinfo.time = time.Now()
 	}
@@ -213,7 +215,7 @@ func (sinfo *searchInfo) checkDHTRes(res *dhtRes) bool {
 		}
 		// Cleanup
 		if _, isIn := sinfo.searches.searches[sinfo.dest]; isIn {
-			sinfo.searches.router.core.log.Debugln("Finished search:", sinfo.dest, sinfo.send, sinfo.recv)
+			sinfo.searches.router.core.log.Debugln("Finished search:", &sinfo.dest, sinfo.send, sinfo.recv)
 			delete(sinfo.searches.searches, res.Dest)
 		}
 	}

src/yggdrasil/session.go

@@ -43,7 +43,6 @@ type sessionInfo struct {
 	time          time.Time           // Time we last received a packet
 	mtuTime       time.Time           // time myMTU was last changed
 	pingTime      time.Time           // time the first ping was sent since the last received packet
-	pingSend      time.Time           // time the last ping was sent
 	coords        []byte              // coords of destination
 	reset         bool                // reset if coords change
 	tstamp        int64               // ATOMIC - tstamp from their last session ping, replay attack mitigation
@@ -197,7 +196,6 @@ func (ss *sessions) createSession(theirPermKey *crypto.BoxPubKey) *sessionInfo {
 	sinfo.time = now
 	sinfo.mtuTime = now
 	sinfo.pingTime = now
-	sinfo.pingSend = now
 	sinfo.init = make(chan struct{})
 	sinfo.cancel = util.NewCancellation()
 	higher := false