dht: even more logging.

routing/dht/dht.go

@@ -89,6 +89,11 @@ func (dht *IpfsDHT) LocalPeer() peer.ID {
 	return dht.self
 }
 
+// log returns the dht's logger
+func (dht *IpfsDHT) log() eventlog.EventLogger {
+	return log.Prefix("dht(%s)", dht.self)
+}
+
 // Connect to a new peer at the given address, ping and add to the routing table
 func (dht *IpfsDHT) Connect(ctx context.Context, npeer peer.ID) error {
 	// TODO: change interface to accept a PeerInfo as well.

routing/dht/query.go

@@ -7,6 +7,7 @@ import (
 	queue "github.com/jbenet/go-ipfs/p2p/peer/queue"
 	"github.com/jbenet/go-ipfs/routing"
 	u "github.com/jbenet/go-ipfs/util"
+	eventlog "github.com/jbenet/go-ipfs/util/eventlog"
 	pset "github.com/jbenet/go-ipfs/util/peerset"
 	todoctr "github.com/jbenet/go-ipfs/util/todocounter"
 
@@ -55,32 +56,18 @@ func (q *dhtQuery) Run(ctx context.Context, peers []peer.ID) (*dhtQueryResult, e
 }
 
 type dhtQueryRunner struct {
+	query          *dhtQuery        // query to run
+	peersSeen      *pset.PeerSet    // all peers queried. prevent querying same peer 2x
+	peersToQuery   *queue.ChanQueue // peers remaining to be queried
+	peersRemaining todoctr.Counter  // peersToQuery + currently processing
 
-	// the query to run
-	query *dhtQuery
+	result *dhtQueryResult // query result
+	errs   []error         // result errors. maybe should be a map[peer.ID]error
 
-	// peersToQuery is a list of peers remaining to query
-	peersToQuery *queue.ChanQueue
+	rateLimit chan struct{} // processing semaphore
+	log       eventlog.EventLogger
 
-	// peersSeen are all the peers queried. used to prevent querying same peer 2x
-	peersSeen *pset.PeerSet
-
-	// rateLimit is a channel used to rate limit our processing (semaphore)
-	rateLimit chan struct{}
-
-	// peersRemaining is a counter of peers remaining (toQuery + processing)
-	peersRemaining todoctr.Counter
-
-	// context group
 	cg ctxgroup.ContextGroup
-
-	// result
-	result *dhtQueryResult
-
-	// result errors
-	errs []error
-
-	// lock for concurrent access to fields
 	sync.RWMutex
 }
 
@@ -96,6 +83,11 @@ func newQueryRunner(ctx context.Context, q *dhtQuery) *dhtQueryRunner {
 }
 
 func (r *dhtQueryRunner) Run(peers []peer.ID) (*dhtQueryResult, error) {
+	log := log.Prefix("dht(%s).Query(%s).Run(%d)", r.query.dht.self, r.query.key, len(peers))
+	r.log = log
+	log.Debug("enter")
+	defer log.Debug("end")
+
 	log.Debugf("Run query with %d peers.", len(peers))
 	if len(peers) == 0 {
 		log.Warning("Running query with no peers!")
@@ -115,6 +107,7 @@ func (r *dhtQueryRunner) Run(peers []peer.ID) (*dhtQueryResult, error) {
 	// go do this thing.
 	// do it as a child func to make sure Run exits
 	// ONLY AFTER spawn workers has exited.
+	log.Debugf("go spawn workers")
 	r.cg.AddChildFunc(r.spawnWorkers)
 
 	// so workers are working.
@@ -124,41 +117,45 @@ func (r *dhtQueryRunner) Run(peers []peer.ID) (*dhtQueryResult, error) {
 
 	select {
 	case <-r.peersRemaining.Done():
+		log.Debug("all peers ended")
 		r.cg.Close()
 		r.RLock()
 		defer r.RUnlock()
 
 		if len(r.errs) > 0 {
-			err = r.errs[0]
+			err = r.errs[0] // take the first?
 		}
 
 	case <-r.cg.Closed():
+		log.Debug("r.cg.Closed()")
+
 		r.RLock()
 		defer r.RUnlock()
 		err = r.cg.Context().Err() // collect the error.
 	}
 
 	if r.result != nil && r.result.success {
+		log.Debug("success: %s", r.result)
 		return r.result, nil
 	}
 
+	log.Debug("failure: %s", err)
 	return nil, err
 }
 
 func (r *dhtQueryRunner) addPeerToQuery(ctx context.Context, next peer.ID) {
 	// if new peer is ourselves...
 	if next == r.query.dht.self {
+		r.log.Debug("addPeerToQuery skip self")
 		return
 	}
 
 	if !r.peersSeen.TryAdd(next) {
-		log.Debug("query peer was already seen")
+		r.log.Debugf("addPeerToQuery skip seen %s", next)
 		return
 	}
 
-	log.Debugf("adding peer to query: %v", next)
-
-	// do this after unlocking to prevent possible deadlocks.
+	r.log.Debugf("addPeerToQuery adding %s", next)
 	r.peersRemaining.Increment(1)
 	select {
 	case r.peersToQuery.EnqChan <- next:
@@ -167,6 +164,10 @@ func (r *dhtQueryRunner) addPeerToQuery(ctx context.Context, next peer.ID) {
 }
 
 func (r *dhtQueryRunner) spawnWorkers(parent ctxgroup.ContextGroup) {
+	log := r.log.Prefix("spawnWorkers")
+	log.Debugf("begin")
+	defer log.Debugf("end")
+
 	for {
 
 		select {
@@ -192,7 +193,9 @@ func (r *dhtQueryRunner) spawnWorkers(parent ctxgroup.ContextGroup) {
 }
 
 func (r *dhtQueryRunner) queryPeer(cg ctxgroup.ContextGroup, p peer.ID) {
-	log.Debugf("spawned worker for: %v", p)
+	log := r.log.Prefix("queryPeer(%s)", p)
+	log.Debugf("spawned")
+	defer log.Debugf("finished")
 
 	// make sure we rate limit concurrency.
 	select {
@@ -203,34 +206,36 @@ func (r *dhtQueryRunner) queryPeer(cg ctxgroup.ContextGroup, p peer.ID) {
 	}
 
 	// ok let's do this!
-	log.Debugf("running worker for: %v", p)
+	log.Debugf("running")
 
 	// make sure we do this when we exit
 	defer func() {
 		// signal we're done proccessing peer p
-		log.Debugf("completing worker for: %v", p)
+		log.Debugf("completed")
 		r.peersRemaining.Decrement(1)
 		r.rateLimit <- struct{}{}
 	}()
 
 	// make sure we're connected to the peer.
 	if conns := r.query.dht.host.Network().ConnsToPeer(p); len(conns) == 0 {
-		log.Infof("worker for: %v -- not connected. dial start", p)
+		log.Infof("not connected. dialing.")
 
 		pi := peer.PeerInfo{ID: p}
 		if err := r.query.dht.host.Connect(cg.Context(), pi); err != nil {
-			log.Debugf("ERROR worker for: %v -- err connecting: %v", p, err)
+			log.Debugf("Error connecting: %s", err)
 			r.Lock()
 			r.errs = append(r.errs, err)
 			r.Unlock()
 			return
 		}
 
-		log.Infof("worker for: %v -- not connected. dial success!", p)
+		log.Debugf("connected. dial success.")
 	}
 
 	// finally, run the query against this peer
+	log.Debugf("query running")
 	res, err := r.query.qfunc(cg.Context(), p)
+	log.Debugf("query finished")
 
 	if err != nil {
 		log.Debugf("ERROR worker for: %v %v", p, err)
@@ -239,7 +244,7 @@ func (r *dhtQueryRunner) queryPeer(cg ctxgroup.ContextGroup, p peer.ID) {
 		r.Unlock()
 
 	} else if res.success {
-		log.Debugf("SUCCESS worker for: %v", p, res)
+		log.Debugf("SUCCESS worker for: %v %s", p, res)
 		r.Lock()
 		r.result = res
 		r.Unlock()

routing/dht/routing.go

 package dht
 
 import (
-	"fmt"
 	"math"
 	"sync"
 
@@ -66,25 +65,29 @@ func (dht *IpfsDHT) PutValue(ctx context.Context, key u.Key, value []byte) error
 // If the search does not succeed, a multiaddr string of a closer peer is
 // returned along with util.ErrSearchIncomplete
 func (dht *IpfsDHT) GetValue(ctx context.Context, key u.Key) ([]byte, error) {
-	log.Debugf("Get Value [%s]", key)
+	log := dht.log().Prefix("GetValue(%s)", key)
+	log.Debugf("start")
+	defer log.Debugf("end")
 
 	// If we have it local, dont bother doing an RPC!
 	val, err := dht.getLocal(key)
 	if err == nil {
-		log.Debug("Got value locally!")
+		log.Debug("have it locally")
 		return val, nil
 	}
 
 	// get closest peers in the routing table
+	rtp := dht.routingTable.ListPeers()
+	log.Debugf("peers in rt: %s", len(rtp), rtp)
+
 	closest := dht.routingTable.NearestPeers(kb.ConvertKey(key), PoolSize)
 	if closest == nil || len(closest) == 0 {
-		log.Warning("Got no peers back from routing table!")
+		log.Warning("No peers from routing table!")
 		return nil, errors.Wrap(kb.ErrLookupFailure)
 	}
 
 	// setup the Query
 	query := dht.newQuery(key, func(ctx context.Context, p peer.ID) (*dhtQueryResult, error) {
-
 		val, peers, err := dht.getValueOrPeers(ctx, p, key)
 		if err != nil {
 			return nil, err
@@ -117,9 +120,13 @@ func (dht *IpfsDHT) GetValue(ctx context.Context, key u.Key) ([]byte, error) {
 
 // Provide makes this node announce that it can provide a value for the given key
 func (dht *IpfsDHT) Provide(ctx context.Context, key u.Key) error {
-
+	log := dht.log().Prefix("Provide(%s)", key)
+	log.Debugf("start", key)
 	log.Event(ctx, "provideBegin", &key)
+	defer log.Debugf("end", key)
 	defer log.Event(ctx, "provideEnd", &key)
+
+	// add self locally
 	dht.providers.AddProvider(key, dht.self)
 
 	peers, err := dht.getClosestPeers(ctx, key)
@@ -132,6 +139,7 @@ func (dht *IpfsDHT) Provide(ctx context.Context, key u.Key) error {
 		wg.Add(1)
 		go func(p peer.ID) {
 			defer wg.Done()
+			log.Debugf("putProvider(%s, %s)", key, p)
 			err := dht.putProvider(ctx, p, string(key))
 			if err != nil {
 				log.Error(err)
@@ -231,9 +239,12 @@ func (dht *IpfsDHT) FindProvidersAsync(ctx context.Context, key u.Key, count int
 }
 
 func (dht *IpfsDHT) findProvidersAsyncRoutine(ctx context.Context, key u.Key, count int, peerOut chan peer.PeerInfo) {
+	log := dht.log().Prefix("FindProviders(%s)", key)
+
 	defer close(peerOut)
 	defer log.Event(ctx, "findProviders end", &key)
-	log.Debugf("%s FindProviders %s", dht.self, key)
+	log.Debug("begin")
+	defer log.Debug("begin")
 
 	ps := pset.NewLimited(count)
 	provs := dht.providers.GetProviders(ctx, key)
@@ -255,25 +266,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)
+		log := log.Prefix("Query(%s)", p)
+		log.Debugf("begin")
+		defer log.Debugf("end")
 
 		pmes, err := dht.findProvidersSingle(ctx, p, key)
 		if err != nil {
 			return nil, err
 		}
 
-		log.Debugf("%s got %d provider entries", reqDesc, len(pmes.GetProviderPeers()))
+		log.Debugf("%d provider entries", len(pmes.GetProviderPeers()))
 		provs := pb.PBPeersToPeerInfos(pmes.GetProviderPeers())
-		log.Debugf("%s got %d provider entries decoded", reqDesc, len(provs))
+		log.Debugf("%d provider entries decoded", len(provs))
 
 		// Add unique providers from request, up to 'count'
 		for _, prov := range provs {
-			log.Debugf("%s got provider: %s", reqDesc, prov)
+			log.Debugf("got provider: %s", prov)
 			if ps.TryAdd(prov.ID) {
-				log.Debugf("%s using provider: %s", reqDesc, prov)
+				log.Debugf("using provider: %s", prov)
 				select {
 				case peerOut <- prov:
 				case <-ctx.Done():
@@ -282,7 +292,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)
+				log.Debugf("got enough providers (%d/%d)", ps.Size(), count)
 				return &dhtQueryResult{success: true}, nil
 			}
 		}
@@ -290,14 +300,14 @@ 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)
+		log.Debugf("got closer peers: %d %s", len(clpeers), clpeers)
 		return &dhtQueryResult{closerPeers: clpeers}, nil
 	})
 
 	peers := dht.routingTable.NearestPeers(kb.ConvertKey(key), AlphaValue)
 	_, err := query.Run(ctx, peers)
 	if err != nil {
-		log.Errorf("FindProviders Query error: %s", err)
+		log.Errorf("Query error: %s", err)
 	}
 }