From c8be55cfd7ab4b6156a59f05d3aeb0df3fdb32a6 Mon Sep 17 00:00:00 2001 From: Alex Grintsvayg Date: Fri, 22 Jun 2018 09:30:16 -0400 Subject: [PATCH] better nodefinder logging --- db/db.go | 4 ++-- dht/node_finder.go | 25 +++++++++++++++---------- dht/token_cache.go | 2 ++ prism/prism.go | 2 +- 4 files changed, 20 insertions(+), 13 deletions(-) diff --git a/db/db.go b/db/db.go index f3fc445..d388570 100644 --- a/db/db.go +++ b/db/db.go @@ -236,8 +236,8 @@ func (s *SQL) GetHashRange() (string, string, error) { return min, max, err } -// GetHashesInRange gets blobs with hashes in a given range, and sends the hashes into a channel -func (s *SQL) GetHashesInRange(ctx context.Context, start, end bits.Bitmap) (ch chan bits.Bitmap, ech chan error) { +// GetStoredHashesInRange gets stored blobs with hashes in a given range, and sends the hashes into a channel +func (s *SQL) GetStoredHashesInRange(ctx context.Context, start, end bits.Bitmap) (ch chan bits.Bitmap, ech chan error) { ch = make(chan bits.Bitmap) ech = make(chan error) diff --git a/dht/node_finder.go b/dht/node_finder.go index cc57d1a..ad5f894 100644 --- a/dht/node_finder.go +++ b/dht/node_finder.go @@ -69,9 +69,9 @@ func (cf *contactFinder) Stop() { func (cf *contactFinder) Find() ([]Contact, bool, error) { if cf.findValue { - log.Debugf("[%s] find %s: starting iterativeFindValue", cf.node.id.HexShort(), cf.target.HexShort()) + cf.debug("starting iterativeFindValue") } else { - log.Debugf("[%s] find %s: starting iterativeFindNode", cf.node.id.HexShort(), cf.target.HexShort()) + cf.debug("starting iterativeFindNode") } cf.appendNewToShortlist(cf.node.rt.GetClosest(cf.target, alpha)) if len(cf.shortlist) == 0 { @@ -108,9 +108,9 @@ func (cf *contactFinder) Find() ([]Contact, bool, error) { } func (cf *contactFinder) iterationWorker(num int) { - log.Debugf("[%s] find %s: starting worker %d", cf.node.id.HexShort(), cf.target.HexShort(), num) + cf.debug("starting worker %d", num) defer func() { - log.Debugf("[%s] find %s: stopping worker %d", cf.node.id.HexShort(), cf.target.HexShort(), num) + cf.debug("stopping worker %d", num) }() for { @@ -133,7 +133,7 @@ func (cf *contactFinder) iterationWorker(num int) { req.Method = findNodeMethod } - log.Debugf("[%s] find %s: worker %d: contacting %s", cf.node.id.HexShort(), cf.target.HexShort(), num, contact.ID.HexShort()) + cf.debug("worker %d: contacting %s", num, contact.ID.HexShort()) cf.incrementOutstanding() @@ -142,23 +142,23 @@ func (cf *contactFinder) iterationWorker(num int) { select { case res = <-resCh: case <-cf.stop.Ch(): - log.Debugf("[%s] find %s: worker %d: canceled", cf.node.id.HexShort(), cf.target.HexShort(), num) + cf.debug("worker %d: canceled", num) cancel() return } if res == nil { // nothing to do, response timed out - log.Debugf("[%s] find %s: worker %d: search canceled or timed out waiting for %s", cf.node.id.HexShort(), cf.target.HexShort(), num, contact.ID.HexShort()) + cf.debug("worker %d: search canceled or timed out waiting for %s", num, contact.ID.HexShort()) } else if cf.findValue && res.FindValueKey != "" { - log.Debugf("[%s] find %s: worker %d: got value", cf.node.id.HexShort(), cf.target.HexShort(), num) + cf.debug("worker %d: got value", num) cf.findValueMutex.Lock() cf.findValueResult = res.Contacts cf.findValueMutex.Unlock() cf.stop.Stop() return } else { - log.Debugf("[%s] find %s: worker %d: got contacts", cf.node.id.HexShort(), cf.target.HexShort(), num) + cf.debug("worker %d: got contacts", num) cf.insertIntoActiveList(contact) cf.appendNewToShortlist(res.Contacts) } @@ -167,7 +167,7 @@ func (cf *contactFinder) iterationWorker(num int) { } if cf.isSearchFinished() { - log.Debugf("[%s] find %s: worker %d: search is finished", cf.node.id.HexShort(), cf.target.HexShort(), num) + cf.debug("worker %d: search is finished", num) cf.stop.Stop() return } @@ -270,6 +270,11 @@ func (cf *contactFinder) areRequestsOutstanding() bool { return cf.outstandingRequests > 0 } +func (cf *contactFinder) debug(format string, args ...interface{}) { + args = append([]interface{}{cf.node.id.HexShort()}, append([]interface{}{cf.target.Hex()}, args...)...) + log.Debugf("[%s] find %s: "+format, args...) +} + func sortInPlace(contacts []Contact, target bits.Bitmap) { toSort := make([]sortedContact, len(contacts)) diff --git a/dht/token_cache.go b/dht/token_cache.go index 010e0db..e080155 100644 --- a/dht/token_cache.go +++ b/dht/token_cache.go @@ -9,6 +9,8 @@ import ( "github.com/lbryio/lbry.go/stopOnce" ) +// TODO: this should be moved out of dht and into node, and it should be completely hidden inside node. dht should not need to know about tokens + type tokenCacheEntry struct { token string receivedAt time.Time diff --git a/prism/prism.go b/prism/prism.go index ea76472..e71791e 100644 --- a/prism/prism.go +++ b/prism/prism.go @@ -166,7 +166,7 @@ func (p *Prism) AnnounceRange(n, total int) { log.Infof("%s: hash range is now %s to %s", p.dht.ID().HexShort(), r.Start, r.End) ctx, cancel := context.WithCancel(context.Background()) - hashCh, errCh := p.db.GetHashesInRange(ctx, r.Start, r.End) + hashCh, errCh := p.db.GetStoredHashesInRange(ctx, r.Start, r.End) var wg sync.WaitGroup