@cryptotaxi247 / kubo / commits / 25b1d34ae

log(dht): remove lots of query debug logs

the debug log is flooded with pages upon pages of... we've gotta be more judicious with our use of console logs. i'm sure there's interesting actionable information in here. let's use the console logging more like a sniper rifle and less like birdshot. feel free to revert if there are specific critical statements in this changeset 03:05:24.096 DEBUG dht: dht(<peer.ID QmWGN3>).Query(QmXvrpUZXCYaCkf1jfaQTJASS91xd47Yih2rnVC5YbFAAK).Run(3) queryPeer(<peer.ID QmSoLp>) QUERY worker for: <peer.ID QmSoLp> - not found, and no closer peers. prefixlog.go:107 03:05:24.096 DEBUG dht: dht(<peer.ID QmWGN3>).Query(QmXvrpUZXCYaCkf1jfaQTJASS91xd47Yih2rnVC5YbFAAK).Run(3) queryPeer(<peer.ID QmSoLp>) completed prefixlog.go:107 03:05:24.096 DEBUG dht: dht(<peer.ID QmWGN3>).Query(QmXvrpUZXCYaCkf1jfaQTJASS91xd47Yih2rnVC5YbFAAK).Run(3) queryPeer(<peer.ID QmSoLp>) finished prefixlog.go:107 03:05:24.096 DEBUG dht: dht(<peer.ID QmWGN3>) FindProviders(QmXvrpUZXCYaCkf1jfaQTJASS91xd47Yih2rnVC5YbFAAK) Query(<peer.ID QmSoLn>) 0 provider entries prefixlog.go:107 03:05:24.096 DEBUG dht: dht(<peer.ID QmWGN3>) FindProviders(QmXvrpUZXCYaCkf1jfaQTJASS91xd47Yih2rnVC5YbFAAK) Query(<peer.ID QmSoLn>) 0 provider entries decoded prefixlog.go:107 03:05:24.096 DEBUG dht: dht(<peer.ID QmWGN3>) FindProviders(QmXvrpUZXCYaCkf1jfaQTJASS91xd47Yih2rnVC5YbFAAK) Query(<peer.ID QmSoLn>) got closer peers: 0 [] prefixlog.go:107 03:05:24.097 DEBUG dht: dht(<peer.ID QmWGN3>) FindProviders(QmXvrpUZXCYaCkf1jfaQTJASS91xd47Yih2rnVC5YbFAAK) Query(<peer.ID QmSoLn>) end prefixlog.go:107 03:05:24.097 DEBUG dht: dht(<peer.ID QmWGN3>).Query(QmXvrpUZXCYaCkf1jfaQTJASS91xd47Yih2rnVC5YbFAAK).Run(3) queryPeer(<peer.ID QmSoLn>) query finished prefixlog.go:107 03:05:24.097 DEBUG dht: dht(<peer.ID QmWGN3>).Query(QmXvrpUZXCYaCkf1jfaQTJASS91xd47Yih2rnVC5YbFAAK).Run(3) queryPeer(<peer.ID QmSoLn>) QUERY worker for: <peer.ID QmSoLn> - not found, and no closer peers. prefixlog.go:107 03:05:24.097 DEBUG dht: dht(<peer.ID QmWGN3>).Query(QmXvrpUZXCYaCkf1jfaQTJASS91xd47Yih2rnVC5YbFAAK).Run(3) queryPeer(<peer.ID QmSoLn>) completed prefixlog.go:107 03:05:24.097 DEBUG dht: dht(<peer.ID QmWGN3>).Query(QmXvrpUZXCYaCkf1jfaQTJASS91xd47Yih2rnVC5YbFAAK).Run(3) queryPeer(<peer.ID QmSoLn>) finished prefixlog.go:107 03:05:24.097 DEBUG dht: dht(<peer.ID QmWGN3>).Query(QmXvrpUZXCYaCkf1jfaQTJASS91xd47Yih2rnVC5YbFAAK).Run(3) all peers ended prefixlog.go:107 03:05:24.097 DEBUG dht: dht(<peer.ID QmWGN3>).Query(QmXvrpUZXCYaCkf1jfaQTJASS91xd47Yih2rnVC5YbFAAK).Run(3) spawnWorkers end prefixlog.go:107 03:05:24.097 DEBUG dht: dht(<peer.ID QmWGN3>).Query(QmXvrpUZXCYaCkf1jfaQTJASS91xd47Yih2rnVC5YbFAAK).Run(3) failure: %s routing: not found prefixlog.go:107 03:05:24.097 DEBUG dht: dht(<peer.ID QmWGN3>).Query(QmXvrpUZXCYaCkf1jfaQTJASS91xd47Yih2rnVC5YbFAAK).Run(3) end prefixlog.go:107

Brian Tiger Chow committed Jan 20, 2015 at 03:05 UTC 25b1d34ae03397e0be468ecbd59afc1cf2308d4d
1 file changed +1 -14
routing/dht/query.go
+1 -14
@@ -85,10 +85,7 @@ func newQueryRunner(ctx context.Context, q *dhtQuery) *dhtQueryRunner {
85
86 func (r *dhtQueryRunner) Run(peers []peer.ID) (*dhtQueryResult, error) {
87 r.log = log
88 - log.Debug("enter")
89 - defer log.Debug("end")
88
91 - log.Debugf("Run query with %d peers.", len(peers))
89 if len(peers) == 0 {
90 log.Warning("Running query with no peers!")
91 return nil, nil
@@ -107,7 +104,6 @@ func (r *dhtQueryRunner) Run(peers []peer.ID) (*dhtQueryResult, error) {
104 // go do this thing.
105 // do it as a child func to make sure Run exits
106 // ONLY AFTER spawn workers has exited.
110 - log.Debugf("go spawn workers")
107 r.cg.AddChildFunc(r.spawnWorkers)
108
109 // so workers are working.
@@ -117,7 +113,6 @@ func (r *dhtQueryRunner) Run(peers []peer.ID) (*dhtQueryResult, error) {
113
114 select {
115 case <-r.peersRemaining.Done():
120 - log.Debug("all peers ended")
116 r.cg.Close()
117 r.RLock()
118 defer r.RUnlock()
@@ -139,11 +134,9 @@ func (r *dhtQueryRunner) Run(peers []peer.ID) (*dhtQueryResult, error) {
134 }
135
136 if r.result != nil && r.result.success {
142 - log.Debug("success: %s", r.result)
137 return r.result, nil
138 }
139
146 - log.Debug("failure: %s", err)
140 return nil, err
141 }
142
@@ -155,11 +148,9 @@ func (r *dhtQueryRunner) addPeerToQuery(ctx context.Context, next peer.ID) {
148 }
149
150 if !r.peersSeen.TryAdd(next) {
158 - r.log.Debugf("addPeerToQuery skip seen %s", next)
151 return
152 }
153
162 - r.log.Debugf("addPeerToQuery adding %s", next)
154 r.peersRemaining.Increment(1)
155 select {
156 case r.peersToQuery.EnqChan <- next:
@@ -181,7 +172,6 @@ func (r *dhtQueryRunner) spawnWorkers(parent ctxgroup.ContextGroup) {
172 if !more {
173 return // channel closed.
174 }
184 - log.Debugf("spawning worker for: %v", p)
175
176 // do it as a child func to make sure Run exits
177 // ONLY AFTER spawn workers has exited.
@@ -202,17 +192,16 @@ func (r *dhtQueryRunner) queryPeer(cg ctxgroup.ContextGroup, p peer.ID) {
192 }
193
194 // ok let's do this!
205 - log.Debugf("running")
195
196 // make sure we do this when we exit
197 defer func() {
198 // signal we're done proccessing peer p
210 - log.Debugf("completed")
199 r.peersRemaining.Decrement(1)
200 r.rateLimit <- struct{}{}
201 }()
202
203 // make sure we're connected to the peer.
204 + // FIXME abstract away into the network layer
205 if conns := r.query.dht.host.Network().ConnsToPeer(p); len(conns) == 0 {
206 log.Infof("not connected. dialing.")
207 // while we dial, we do not take up a rate limit. this is to allow
@@ -239,9 +228,7 @@ func (r *dhtQueryRunner) queryPeer(cg ctxgroup.ContextGroup, p peer.ID) {
228 }
229
230 // finally, run the query against this peer
242 - log.Debugf("query running")
231 res, err := r.query.qfunc(cg.Context(), p)
244 - log.Debugf("query finished")
232
233 if err != nil {
234 log.Debugf("ERROR worker for: %v %v", p, err)