changed logging, in dht and elsewhere
- use log.* instead of u.* - use automatic type conversions to .String() (Peer.String() prints nicely, and avoids calling b58 encoding until needed)
Juan Batiz-Benet committed
Oct 7, 2014 at 21:29 UTC
66839fa1dea9628c55e226b48c76f1a7b2789c02
9 files changed
+39
-40
crypto/spipe/handshake.go
+2
-2
@@ -101,7 +101,7 @@ func (s *SecurePipe) handshake() error {
101
if err != nil {
102
return err
103
}
104
- u.DOut("[%s] Remote Peer Identified as %s\n", s.local, s.remote)
104
+ u.DOut("%s Remote Peer Identified as %s\n", s.local, s.remote)
105
106
exchange, err := selectBest(SupportedExchanges, proposeResp.GetExchanges())
107
if err != nil {
@@ -205,7 +205,7 @@ func (s *SecurePipe) handshake() error {
205
return errors.New("Negotiation failed.")
206
}
207
208
- u.DOut("[%s] handshake: Got node id: %s\n", s.local, s.remote)
208
+ u.DOut("%s handshake: Got node id: %s\n", s.local, s.remote)
209
return nil
210
}
211
peer/peer.go
+1
-1
@@ -55,7 +55,7 @@ type Peer struct {
55
56
// String prints out the peer.
57
func (p *Peer) String() string {
58
- return "[Peer " + p.ID.Pretty() + "]"
58
+ return "[Peer " + p.ID.String() + "]"
59
}
60
61
// Key returns the ID as a Key (string) for maps.
routing/dht/dht.go
+3
-3
@@ -221,7 +221,7 @@ func (dht *IpfsDHT) putProvider(ctx context.Context, p *peer.Peer, key string) e
221
return err
222
}
223
224
- log.Debug("[%s] putProvider: %s for %s", dht.self, p, key)
224
+ log.Debug("%s putProvider: %s for %s", dht.self, p, key)
225
if *rpmes.Key != *pmes.Key {
226
return errors.New("provider not added correctly")
227
}
@@ -345,7 +345,7 @@ func (dht *IpfsDHT) putLocal(key u.Key, value []byte) error {
345
// Update signals to all routingTables to Update their last-seen status
346
// on the given peer.
347
func (dht *IpfsDHT) Update(p *peer.Peer) {
348
- log.Debug("updating peer: [%s] latency = %f\n", p, p.GetLatency().Seconds())
348
+ log.Debug("updating peer: %s latency = %f\n", p, p.GetLatency().Seconds())
349
removedCount := 0
350
for _, route := range dht.routingTables {
351
removed := route.Update(p)
@@ -401,7 +401,7 @@ func (dht *IpfsDHT) addProviders(key u.Key, peers []*Message_Peer) []*peer.Peer
401
continue
402
}
403
404
- log.Debug("[%s] adding provider: %s for %s", dht.self, p, key)
404
+ log.Debug("%s adding provider: %s for %s", dht.self, p, key)
405
406
// Dont add outselves to the list
407
if p.ID.Equal(dht.self.ID) {
routing/dht/dht_test.go
+1
-1
@@ -287,7 +287,7 @@ func TestProvidesAsync(t *testing.T) {
287
select {
288
case p := <-provs:
289
if !p.ID.Equal(dhts[3].self.ID) {
290
- t.Fatalf("got a provider, but not the right one. %v", p.ID.Pretty())
290
+ t.Fatalf("got a provider, but not the right one. %s", p)
291
}
292
case <-ctx.Done():
293
t.Fatal("Didnt get back providers")
routing/dht/handlers.go
+14
-15
@@ -38,7 +38,7 @@ func (dht *IpfsDHT) handlerForMsgType(t Message_MessageType) dhtHandler {
38
}
39
40
func (dht *IpfsDHT) handleGetValue(p *peer.Peer, pmes *Message) (*Message, error) {
41
- u.DOut("[%s] handleGetValue for key: %s\n", dht.self.ID.Pretty(), pmes.GetKey())
41
+ log.Debug("%s handleGetValue for key: %s\n", dht.self, pmes.GetKey())
42
43
// setup response
44
resp := newMessage(pmes.GetType(), pmes.GetKey(), pmes.GetClusterLevel())
@@ -50,10 +50,10 @@ func (dht *IpfsDHT) handleGetValue(p *peer.Peer, pmes *Message) (*Message, error
50
}
51
52
// let's first check if we have the value locally.
53
- u.DOut("[%s] handleGetValue looking into ds\n", dht.self.ID.Pretty())
53
+ log.Debug("%s handleGetValue looking into ds\n", dht.self)
54
dskey := u.Key(pmes.GetKey()).DsKey()
55
iVal, err := dht.datastore.Get(dskey)
56
- u.DOut("[%s] handleGetValue looking into ds GOT %v\n", dht.self.ID.Pretty(), iVal)
56
+ log.Debug("%s handleGetValue looking into ds GOT %v\n", dht.self, iVal)
57
58
// if we got an unexpected error, bail.
59
if err != nil && err != ds.ErrNotFound {
@@ -65,7 +65,7 @@ func (dht *IpfsDHT) handleGetValue(p *peer.Peer, pmes *Message) (*Message, error
65
66
// if we have the value, send it back
67
if err == nil {
68
- u.DOut("[%s] handleGetValue success!\n", dht.self.ID.Pretty())
68
+ log.Debug("%s handleGetValue success!\n", dht.self)
69
70
byts, ok := iVal.([]byte)
71
if !ok {
@@ -78,14 +78,14 @@ func (dht *IpfsDHT) handleGetValue(p *peer.Peer, pmes *Message) (*Message, error
78
// if we know any providers for the requested value, return those.
79
provs := dht.providers.GetProviders(u.Key(pmes.GetKey()))
80
if len(provs) > 0 {
81
- u.DOut("handleGetValue returning %d provider[s]\n", len(provs))
81
+ log.Debug("handleGetValue returning %d provider[s]\n", len(provs))
82
resp.ProviderPeers = peersToPBPeers(provs)
83
}
84
85
// Find closest peer on given cluster to desired key and reply with that info
86
closer := dht.betterPeerToQuery(pmes)
87
if closer != nil {
88
- u.DOut("handleGetValue returning a closer peer: '%s'\n", closer.ID.Pretty())
88
+ log.Debug("handleGetValue returning a closer peer: '%s'\n", closer)
89
resp.CloserPeers = peersToPBPeers([]*peer.Peer{closer})
90
}
91
@@ -98,12 +98,12 @@ func (dht *IpfsDHT) handlePutValue(p *peer.Peer, pmes *Message) (*Message, error
98
defer dht.dslock.Unlock()
99
dskey := u.Key(pmes.GetKey()).DsKey()
100
err := dht.datastore.Put(dskey, pmes.GetValue())
101
- u.DOut("[%s] handlePutValue %v %v\n", dht.self.ID.Pretty(), dskey, pmes.GetValue())
101
+ log.Debug("%s handlePutValue %v %v\n", dht.self, dskey, pmes.GetValue())
102
return pmes, err
103
}
104
105
func (dht *IpfsDHT) handlePing(p *peer.Peer, pmes *Message) (*Message, error) {
106
- u.DOut("[%s] Responding to ping from [%s]!\n", dht.self.ID.Pretty(), p.ID.Pretty())
106
+ log.Debug("%s Responding to ping from %s!\n", dht.self, p)
107
return pmes, nil
108
}
109
@@ -119,16 +119,16 @@ func (dht *IpfsDHT) handleFindPeer(p *peer.Peer, pmes *Message) (*Message, error
119
}
120
121
if closest == nil {
122
- u.PErr("handleFindPeer: could not find anything.\n")
122
+ log.Error("handleFindPeer: could not find anything.\n")
123
return resp, nil
124
}
125
126
if len(closest.Addresses) == 0 {
127
- u.PErr("handleFindPeer: no addresses for connected peer...\n")
127
+ log.Error("handleFindPeer: no addresses for connected peer...\n")
128
return resp, nil
129
}
130
131
- u.DOut("handleFindPeer: sending back '%s'\n", closest.ID.Pretty())
131
+ log.Debug("handleFindPeer: sending back '%s'\n", closest)
132
resp.CloserPeers = peersToPBPeers([]*peer.Peer{closest})
133
return resp, nil
134
}
@@ -140,7 +140,7 @@ func (dht *IpfsDHT) handleGetProviders(p *peer.Peer, pmes *Message) (*Message, e
140
dsk := u.Key(pmes.GetKey()).DsKey()
141
has, err := dht.datastore.Has(dsk)
142
if err != nil && err != ds.ErrNotFound {
143
- u.PErr("unexpected datastore error: %v\n", err)
143
+ log.Error("unexpected datastore error: %v\n", err)
144
has = false
145
}
146
@@ -172,8 +172,7 @@ type providerInfo struct {
172
func (dht *IpfsDHT) handleAddProvider(p *peer.Peer, pmes *Message) (*Message, error) {
173
key := u.Key(pmes.GetKey())
174
175
- u.DOut("[%s] Adding [%s] as a provider for '%s'\n",
176
- dht.self.ID.Pretty(), p.ID.Pretty(), peer.ID(key).Pretty())
175
+ log.Debug("%s adding %s as a provider for '%s'\n", dht.self, p, peer.ID(key))
176
177
dht.providers.AddProvider(key, p)
178
return pmes, nil // send back same msg as confirmation.
@@ -192,7 +191,7 @@ func (dht *IpfsDHT) handleDiagnostic(p *peer.Peer, pmes *Message) (*Message, err
191
for _, ps := range seq {
192
_, err := msg.FromObject(ps, pmes)
193
if err != nil {
195
- u.PErr("handleDiagnostics error creating message: %v\n", err)
194
+ log.Error("handleDiagnostics error creating message: %v\n", err)
195
continue
196
}
197
// dht.sender.SendRequest(context.TODO(), mes)
routing/dht/query.go
+9
-9
@@ -151,7 +151,7 @@ func (r *dhtQueryRunner) Run(peers []*peer.Peer) (*dhtQueryResult, error) {
151
func (r *dhtQueryRunner) addPeerToQuery(next *peer.Peer, benchmark *peer.Peer) {
152
if next == nil {
153
// wtf why are peers nil?!?
154
- u.PErr("Query getting nil peers!!!\n")
154
+ log.Error("Query getting nil peers!!!\n")
155
return
156
}
157
@@ -170,7 +170,7 @@ func (r *dhtQueryRunner) addPeerToQuery(next *peer.Peer, benchmark *peer.Peer) {
170
r.peersSeen[next.Key()] = next
171
r.Unlock()
172
173
- log.Debug("adding peer to query: %v\n", next.ID.Pretty())
173
+ log.Debug("adding peer to query: %v\n", next)
174
175
// do this after unlocking to prevent possible deadlocks.
176
r.peersRemaining.Increment(1)
@@ -194,14 +194,14 @@ func (r *dhtQueryRunner) spawnWorkers() {
194
if !more {
195
return // channel closed.
196
}
197
- u.DOut("spawning worker for: %v\n", p.ID.Pretty())
197
+ log.Debug("spawning worker for: %v\n", p)
198
go r.queryPeer(p)
199
}
200
}
201
}
202
203
func (r *dhtQueryRunner) queryPeer(p *peer.Peer) {
204
- u.DOut("spawned worker for: %v\n", p.ID.Pretty())
204
+ log.Debug("spawned worker for: %v\n", p)
205
206
// make sure we rate limit concurrency.
207
select {
@@ -211,33 +211,33 @@ func (r *dhtQueryRunner) queryPeer(p *peer.Peer) {
211
return
212
}
213
214
- u.DOut("running worker for: %v\n", p.ID.Pretty())
214
+ log.Debug("running worker for: %v\n", p)
215
216
// finally, run the query against this peer
217
res, err := r.query.qfunc(r.ctx, p)
218
219
if err != nil {
220
- u.DOut("ERROR worker for: %v %v\n", p.ID.Pretty(), err)
220
+ log.Debug("ERROR worker for: %v %v\n", p, err)
221
r.Lock()
222
r.errs = append(r.errs, err)
223
r.Unlock()
224
225
} else if res.success {
226
- u.DOut("SUCCESS worker for: %v\n", p.ID.Pretty(), res)
226
+ log.Debug("SUCCESS worker for: %v\n", p, res)
227
r.Lock()
228
r.result = res
229
r.Unlock()
230
r.cancel() // signal to everyone that we're done.
231
232
} else if res.closerPeers != nil {
233
- u.DOut("PEERS CLOSER -- worker for: %v\n", p.ID.Pretty())
233
+ log.Debug("PEERS CLOSER -- worker for: %v\n", p)
234
for _, next := range res.closerPeers {
235
r.addPeerToQuery(next, p)
236
}
237
}
238
239
// signal we're done proccessing peer p
240
- u.DOut("completing worker for: %v\n", p.ID.Pretty())
240
+ log.Debug("completing worker for: %v\n", p)
241
r.peersRemaining.Decrement(1)
242
r.rateLimit <- struct{}{}
243
}
routing/dht/routing.go
+6
-6
@@ -18,7 +18,7 @@ import (
18
// PutValue adds value corresponding to given Key.
19
// This is the top level "Store" operation of the DHT
20
func (dht *IpfsDHT) PutValue(ctx context.Context, key u.Key, value []byte) error {
21
- log.Debug("PutValue %s", key.Pretty())
21
+ log.Debug("PutValue %s", key)
22
err := dht.putLocal(key, value)
23
if err != nil {
24
return err
@@ -31,7 +31,7 @@ func (dht *IpfsDHT) PutValue(ctx context.Context, key u.Key, value []byte) error
31
}
32
33
query := newQuery(key, func(ctx context.Context, p *peer.Peer) (*dhtQueryResult, error) {
34
- log.Debug("[%s] PutValue qry part %v", dht.self.ID.Pretty(), p.ID.Pretty())
34
+ log.Debug("%s PutValue qry part %v", dht.self, p)
35
err := dht.putValueToNetwork(ctx, p, string(key), value)
36
if err != nil {
37
return nil, err
@@ -47,7 +47,7 @@ func (dht *IpfsDHT) PutValue(ctx context.Context, key u.Key, value []byte) error
47
// If the search does not succeed, a multiaddr string of a closer peer is
48
// returned along with util.ErrSearchIncomplete
49
func (dht *IpfsDHT) GetValue(ctx context.Context, key u.Key) ([]byte, error) {
50
- log.Debug("Get Value [%s]", key.Pretty())
50
+ log.Debug("Get Value [%s]", key)
51
52
// If we have it local, dont bother doing an RPC!
53
// NOTE: this might not be what we want to do...
@@ -189,7 +189,7 @@ func (dht *IpfsDHT) addPeerListAsync(k u.Key, peers []*Message_Peer, ps *peerSet
189
// FindProviders searches for peers who can provide the value for given key.
190
func (dht *IpfsDHT) FindProviders(ctx context.Context, key u.Key) ([]*peer.Peer, error) {
191
// get closest peer
192
- log.Debug("Find providers for: '%s'", key.Pretty())
192
+ log.Debug("Find providers for: '%s'", key)
193
p := dht.routingTables[0].NearestPeer(kb.ConvertKey(key))
194
if p == nil {
195
return nil, nil
@@ -333,11 +333,11 @@ func (dht *IpfsDHT) findPeerMultiple(ctx context.Context, id peer.ID) (*peer.Pee
333
// Ping a peer, log the time it took
334
func (dht *IpfsDHT) Ping(ctx context.Context, p *peer.Peer) error {
335
// Thoughts: maybe this should accept an ID and do a peer lookup?
336
- log.Info("ping %s start", p.ID.Pretty())
336
+ log.Info("ping %s start", p)
337
338
pmes := newMessage(Message_PING, "", 0)
339
_, err := dht.sendRequest(ctx, p, pmes)
340
- log.Info("ping %s end (err = %s)", p.ID.Pretty(), err)
340
+ log.Info("ping %s end (err = %s)", p, err)
341
return err
342
}
343
routing/kbucket/table_test.go
+2
-2
@@ -101,7 +101,7 @@ func TestTableFind(t *testing.T) {
101
rt.Update(peers[i])
102
}
103
104
- t.Logf("Searching for peer: '%s'", peers[2].ID.Pretty())
104
+ t.Logf("Searching for peer: '%s'", peers[2])
105
found := rt.NearestPeer(ConvertPeerID(peers[2].ID))
106
if !found.ID.Equal(peers[2].ID) {
107
t.Fatalf("Failed to lookup known node...")
@@ -118,7 +118,7 @@ func TestTableFindMultiple(t *testing.T) {
118
rt.Update(peers[i])
119
}
120
121
- t.Logf("Searching for peer: '%s'", peers[2].ID.Pretty())
121
+ t.Logf("Searching for peer: '%s'", peers[2])
122
found := rt.NearestPeers(ConvertPeerID(peers[2].ID), 15)
123
if len(found) != 15 {
124
t.Fatalf("Got back different number of peers than we expected.")
util/util.go
+1
-1
@@ -41,7 +41,7 @@ type Key string
41
42
// String is utililty function for printing out keys as strings (Pretty).
43
func (k Key) String() string {
44
- return key.Pretty()
44
+ return k.Pretty()
45
}
46
47
// Pretty returns Key in a b58 encoded string