dht: some provider debug logging

routing/dht/handlers.go

@@ -167,25 +167,31 @@ func (dht *IpfsDHT) handleFindPeer(ctx context.Context, p peer.ID, pmes *pb.Mess
 
 func (dht *IpfsDHT) handleGetProviders(ctx context.Context, p peer.ID, pmes *pb.Message) (*pb.Message, error) {
 	resp := pb.NewMessage(pmes.GetType(), pmes.GetKey(), pmes.GetClusterLevel())
+	key := u.Key(pmes.GetKey())
+
+	// debug logging niceness.
+	reqDesc := fmt.Sprintf("%s handleGetProviders(%s, %s): ", dht.self, p, key)
+	log.Debugf("%s begin", reqDesc)
+	defer log.Debugf("%s end", reqDesc)
 
 	// check if we have this value, to add ourselves as provider.
-	log.Debugf("handling GetProviders: '%s'", u.Key(pmes.GetKey()))
+	has, err := dht.datastore.Has(key.DsKey())
-	dsk := u.Key(pmes.GetKey()).DsKey()
-	has, err := dht.datastore.Has(dsk)
 	if err != nil && err != ds.ErrNotFound {
 		log.Errorf("unexpected datastore error: %v\n", err)
 		has = false
 	}
 
 	// setup providers
-	providers := dht.providers.GetProviders(ctx, u.Key(pmes.GetKey()))
+	providers := dht.providers.GetProviders(ctx, key)
 	if has {
 		providers = append(providers, dht.self)
+		log.Debugf("%s have the value. added self as provider", reqDesc)
 	}
 
 	if providers != nil && len(providers) > 0 {
 		infos := peer.PeerInfos(dht.peerstore, providers)
 		resp.ProviderPeers = pb.PeerInfosToPBPeers(dht.host.Network(), infos)
+		log.Debugf("%s have %d providers: %s", reqDesc, len(providers), infos)
 	}
 
 	// Also send closer peers.
@@ -193,6 +199,7 @@ func (dht *IpfsDHT) handleGetProviders(ctx context.Context, p peer.ID, pmes *pb.
 	if closer != nil {
 		infos := peer.PeerInfos(dht.peerstore, providers)
 		resp.CloserPeers = pb.PeerInfosToPBPeers(dht.host.Network(), infos)
+		log.Debugf("%s have %d closer peers: %s", reqDesc, len(closer), infos)
 	}
 
 	return resp, nil

routing/dht/routing.go

@@ -1,6 +1,7 @@
 package dht
 
 import (
+	"fmt"
 	"math"
 	"sync"
 
@@ -255,16 +256,24 @@ func (dht *IpfsDHT) findProvidersAsyncRoutine(ctx context.Context, key u.Key, co
 	// setup the Query
 	query := dht.newQuery(key, func(ctx context.Context, p peer.ID) (*dhtQueryResult, error) {
 
+		reqDesc := fmt.Sprintf("%s findProviders(%s).Query(%s): ", dht.self, key, p)
+		log.Debugf("%s begin", reqDesc)
+		defer log.Debugf("%s end", reqDesc)
+
 		pmes, err := dht.findProvidersSingle(ctx, p, key)
 		if err != nil {
 			return nil, err
 		}
 
+		log.Debugf("%s got %d provider entries", reqDesc, len(pmes.GetProviderPeers()))
 		provs := pb.PBPeersToPeerInfos(pmes.GetProviderPeers())
+		log.Debugf("%s got %d provider entries decoded", reqDesc, len(provs))
 
 		// Add unique providers from request, up to 'count'
 		for _, prov := range provs {
+			log.Debugf("%s got provider: %s", reqDesc, prov)
 			if ps.TryAdd(prov.ID) {
+				log.Debugf("%s using provider: %s", reqDesc, prov)
 				select {
 				case peerOut <- prov:
 				case <-ctx.Done():
@@ -273,6 +282,7 @@ func (dht *IpfsDHT) findProvidersAsyncRoutine(ctx context.Context, key u.Key, co
 				}
 			}
 			if ps.Size() >= count {
+				log.Debugf("%s got enough providers (%d/%d)", reqDesc, ps.Size(), count)
 				return &dhtQueryResult{success: true}, nil
 			}
 		}
@@ -280,6 +290,7 @@ func (dht *IpfsDHT) findProvidersAsyncRoutine(ctx context.Context, key u.Key, co
 		// Give closer peers back to the query to be queried
 		closer := pmes.GetCloserPeers()
 		clpeers := pb.PBPeersToPeerInfos(closer)
+		log.Debugf("%s got closer peers: %s", reqDesc, clpeers)
 		return &dhtQueryResult{closerPeers: clpeers}, nil
 	})