better nodefinder logging

This commit is contained in:
Alex Grintsvayg 2018-06-22 09:30:16 -04:00
parent c327b6b456
commit c8be55cfd7
4 changed files with 20 additions and 13 deletions

View file

@ -236,8 +236,8 @@ func (s *SQL) GetHashRange() (string, string, error) {
return min, max, err return min, max, err
} }
// GetHashesInRange gets blobs with hashes in a given range, and sends the hashes into a channel // GetStoredHashesInRange gets stored 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) { func (s *SQL) GetStoredHashesInRange(ctx context.Context, start, end bits.Bitmap) (ch chan bits.Bitmap, ech chan error) {
ch = make(chan bits.Bitmap) ch = make(chan bits.Bitmap)
ech = make(chan error) ech = make(chan error)

View file

@ -69,9 +69,9 @@ func (cf *contactFinder) Stop() {
func (cf *contactFinder) Find() ([]Contact, bool, error) { func (cf *contactFinder) Find() ([]Contact, bool, error) {
if cf.findValue { if cf.findValue {
log.Debugf("[%s] find %s: starting iterativeFindValue", cf.node.id.HexShort(), cf.target.HexShort()) cf.debug("starting iterativeFindValue")
} else { } 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)) cf.appendNewToShortlist(cf.node.rt.GetClosest(cf.target, alpha))
if len(cf.shortlist) == 0 { if len(cf.shortlist) == 0 {
@ -108,9 +108,9 @@ func (cf *contactFinder) Find() ([]Contact, bool, error) {
} }
func (cf *contactFinder) iterationWorker(num int) { 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() { 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 { for {
@ -133,7 +133,7 @@ func (cf *contactFinder) iterationWorker(num int) {
req.Method = findNodeMethod 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() cf.incrementOutstanding()
@ -142,23 +142,23 @@ func (cf *contactFinder) iterationWorker(num int) {
select { select {
case res = <-resCh: case res = <-resCh:
case <-cf.stop.Ch(): 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() cancel()
return return
} }
if res == nil { if res == nil {
// nothing to do, response timed out // 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 != "" { } 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.findValueMutex.Lock()
cf.findValueResult = res.Contacts cf.findValueResult = res.Contacts
cf.findValueMutex.Unlock() cf.findValueMutex.Unlock()
cf.stop.Stop() cf.stop.Stop()
return return
} else { } 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.insertIntoActiveList(contact)
cf.appendNewToShortlist(res.Contacts) cf.appendNewToShortlist(res.Contacts)
} }
@ -167,7 +167,7 @@ func (cf *contactFinder) iterationWorker(num int) {
} }
if cf.isSearchFinished() { 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() cf.stop.Stop()
return return
} }
@ -270,6 +270,11 @@ func (cf *contactFinder) areRequestsOutstanding() bool {
return cf.outstandingRequests > 0 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) { func sortInPlace(contacts []Contact, target bits.Bitmap) {
toSort := make([]sortedContact, len(contacts)) toSort := make([]sortedContact, len(contacts))

View file

@ -9,6 +9,8 @@ import (
"github.com/lbryio/lbry.go/stopOnce" "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 { type tokenCacheEntry struct {
token string token string
receivedAt time.Time receivedAt time.Time

View file

@ -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) log.Infof("%s: hash range is now %s to %s", p.dht.ID().HexShort(), r.Start, r.End)
ctx, cancel := context.WithCancel(context.Background()) 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 var wg sync.WaitGroup