p2p/net: dial log -> events
This commit turns all dial logs into log.Events. Everything's great except for one problem: The LoggableMap I'm using does not print out things correctly. I gave it peer.IDs, and Multiaddrs and both got logged as nothing `{}` (didn't even call their String() methods!) So, for now, this function encodes it when called... This is wrong and should be fixed before being merged in. Otherwise we will be constantly encoding peer.IDs and Multiaddrs without needing to. @briantigerchow how do you suggest doing this? I don't know my way around your Loggable.
Juan Batiz-Benet committed
Jan 27, 2015 at 01:22 UTC
9dac5bb7d313cda105f47064caf65766f2651a60
3 files changed
+127
-48
p2p/net/conn/dial.go
+31
-4
@@ -11,6 +11,7 @@ import (
11
ma "github.com/jbenet/go-ipfs/Godeps/_workspace/src/github.com/jbenet/go-multiaddr"
12
manet "github.com/jbenet/go-ipfs/Godeps/_workspace/src/github.com/jbenet/go-multiaddr-net"
13
reuseport "github.com/jbenet/go-ipfs/Godeps/_workspace/src/github.com/jbenet/go-reuseport"
14
+ lgbl "github.com/jbenet/go-ipfs/util/eventlog/loggables"
15
16
addrutil "github.com/jbenet/go-ipfs/p2p/net/swarm/addr"
17
peer "github.com/jbenet/go-ipfs/p2p/peer"
@@ -26,9 +27,13 @@ func (d *Dialer) String() string {
27
// Ensures raddr is part of peer.Addresses()
28
// Example: d.DialAddr(ctx, peer.Addresses()[0], peer)
29
func (d *Dialer) Dial(ctx context.Context, raddr ma.Multiaddr, remote peer.ID) (Conn, error) {
30
+ logdial := lgbl.Dial("conn", d.LocalPeer, remote, nil, raddr)
31
+ defer log.EventBegin(ctx, "connDial", logdial).Done()
32
33
maconn, err := d.rawConnDial(ctx, raddr, remote)
34
if err != nil {
35
+ logdial["dial"] = "failure"
36
+ logdial["error"] = err
37
return nil, err
38
}
39
@@ -48,11 +53,15 @@ func (d *Dialer) Dial(ctx context.Context, raddr ma.Multiaddr, remote peer.ID) (
53
54
if d.PrivateKey == nil {
55
log.Warning("dialer %s dialing INSECURELY %s at %s!", d, remote, raddr)
56
+ log.Event(ctx, "connDialInsecure", logdial)
57
connOut = c
58
return
59
}
60
+
61
+ defer log.EventBegin(ctx, "connDialEncrypt", logdial).Done()
62
c2, err := newSecureConn(ctx, d.PrivateKey, c)
63
if err != nil {
64
+ logdial["error"] = err
65
errOut = err
66
c.Close()
67
return
@@ -64,12 +73,20 @@ func (d *Dialer) Dial(ctx context.Context, raddr ma.Multiaddr, remote peer.ID) (
73
select {
74
case <-ctx.Done():
75
maconn.Close()
76
+ logdial["error"] = ctx.Err()
77
return nil, ctx.Err()
78
case <-done:
79
// whew, finished.
80
}
81
72
- return connOut, errOut
82
+ if errOut != nil {
83
+ logdial["error"] = errOut
84
+ logdial["dial"] = "failure"
85
+ return nil, errOut
86
+ }
87
+
88
+ logdial["dial"] = "success"
89
+ return connOut, nil
90
}
91
92
// rawConnDial dials the underlying net.Conn + manet.Conns
@@ -82,12 +99,14 @@ func (d *Dialer) rawConnDial(ctx context.Context, raddr ma.Multiaddr, remote pee
99
}
100
101
if strings.HasPrefix(raddr.String(), "/ip4/0.0.0.0") {
102
+ log.Event(ctx, "connDialZeroAddr", lgbl.Dial("conn", d.LocalPeer, remote, nil, raddr))
103
return nil, debugerror.Errorf("Attempted to connect to zero address: %s", raddr)
104
}
105
106
// get local addr to use.
107
laddr := pickLocalAddr(d.LocalAddrs, raddr)
90
- log.Debugf("%s dialing %s -- %s --> %s", d.LocalPeer, remote, laddr, raddr)
108
+ logdial := lgbl.Dial("conn", d.LocalPeer, remote, laddr, raddr)
109
+ defer log.EventBegin(ctx, "connDialRawConn", logdial).Done()
110
111
// make a copy of the manet.Dialer, we may need to change its timeout.
112
madialer := d.Dialer
@@ -99,19 +118,27 @@ func (d *Dialer) rawConnDial(ctx context.Context, raddr ma.Multiaddr, remote pee
118
119
// dial using reuseport.Dialer, because we're probably reusing addrs.
120
// this is optimistic, as the reuseDial may fail to bind the port.
121
+ rpev := log.EventBegin(ctx, "connDialReusePort", logdial)
122
if nconn, retry, reuseErr := reuseDial(madialer.Dialer, laddr, raddr); reuseErr == nil {
123
// if it worked, wrap the raw net.Conn with our manet.Conn
104
- log.Debugf("%s reuse worked! %s %s %s", d.LocalPeer, laddr, nconn.RemoteAddr(), nconn)
124
+ logdial["reuseport"] = "success"
125
+ rpev.Done()
126
return manet.WrapNetConn(nconn)
127
} else if !retry {
128
// reuseDial is sure this is a legitimate dial failure, not a reuseport failure.
129
+ logdial["reuseport"] = "failure"
130
+ logdial["error"] = reuseErr
131
+ rpev.Done()
132
return nil, reuseErr
133
} else {
134
// this is a failure to reuse port. log it.
111
- log.Debugf("%s port reuse failed: %s --> %s -- %s", d.LocalPeer, laddr, raddr, reuseErr)
135
+ logdial["reuseport"] = "retry"
136
+ logdial["error"] = reuseErr
137
+ rpev.Done()
138
}
139
}
140
141
+ defer log.EventBegin(ctx, "connDialManet", logdial).Done()
142
return madialer.Dial(raddr)
143
}
144
p2p/net/swarm/swarm_dial.go
+74
-44
@@ -28,8 +28,16 @@ import (
28
// any may fail if no addr at end
29
// retry dialAttempt x
30
31
+var (
32
+ ErrDialBackoff = errors.New("dial backoff")
33
+ ErrDialFailed = errors.New("dial attempt failed")
34
+ ErrDialToSelf = errors.New("dial to self attempted")
35
+)
36
+
37
// dialAttempts governs how many times a goroutine will try to dial a given peer.
32
-const dialAttempts = 3
38
+// Note: this is down to one, as we have _too many dials_ atm. To add back in,
39
+// add loop back in Dial(.)
40
+const dialAttempts = 1
41
42
// DialTimeout is the amount of time each dial attempt has. We can think about making
43
// this larger down the road, or putting more granular timeouts (i.e. within each
@@ -179,75 +187,96 @@ func (db *dialbackoff) Clear(p peer.ID) {
187
// This allows us to use various transport protocols, do NAT traversal/relay,
188
// etc. to achive connection.
189
func (s *Swarm) Dial(ctx context.Context, p peer.ID) (*Conn, error) {
190
+ var logdial = lgbl.Dial("swarm", s.LocalPeer(), p, nil, nil)
191
if p == s.local {
183
- return nil, errors.New("Attempted connection to self!")
192
+ log.Event(ctx, "swarmDialSelf", logdial)
193
+ return nil, ErrDialToSelf
194
}
195
186
- // this loop is here because dials take time, and we should not be dialing
187
- // the same peer concurrently (silly waste). Additonally, it's structured
188
- // to check s.ConnectionsToPeer(p) _first_, and _between_ attempts because we
189
- // may have received an incoming connection! if so, we no longer must dial.
190
- //
191
- // During the dial attempts, we may be doing the dialing. if not, we wait.
192
- var err error
193
- var conn *Conn
194
- for i := 0; i < dialAttempts; i++ {
195
- // check if we already have an open connection first
196
- cs := s.ConnectionsToPeer(p)
197
- for _, conn = range cs {
198
- if conn != nil { // dump out the first one we find. (TODO pick better)
199
- return conn, nil
200
- }
201
- }
196
+ return s.gatedDialAttempt(ctx, p)
197
+}
198
203
- // check if there's an ongoing dial to this peer
204
- if ok, wait := s.dsync.Lock(p); !ok {
199
+func (s *Swarm) bestConnectionToPeer(p peer.ID) *Conn {
200
+ cs := s.ConnectionsToPeer(p)
201
+ for _, conn := range cs {
202
+ if conn != nil { // dump out the first one we find. (TODO pick better)
203
+ return conn
204
+ }
205
+ }
206
+ return nil
207
+}
208
206
- if s.backf.Backoff(p) {
207
- log.Debugf("backoff")
208
- return nil, fmt.Errorf("%s failed to dial %s, backing off.", s.local, p)
209
- }
209
+// gatedDialAttempt is an attempt to dial a node. It is gated by the swarm's
210
+// dial synchronization systems: dialsync and dialbackoff.
211
+func (s *Swarm) gatedDialAttempt(ctx context.Context, p peer.ID) (*Conn, error) {
212
+ var logdial = lgbl.Dial("swarm", s.LocalPeer(), p, nil, nil)
213
+ defer log.EventBegin(ctx, "swarmDialAttemptSync", logdial).Done()
214
211
- log.Debugf("waiting for ongoing dial")
212
- select {
213
- case <-wait: // wait for that dial to finish.
214
- continue // and see if it worked (loop), OR we got an incoming dial.
215
- case <-ctx.Done(): // or we may have to bail...
216
- return nil, ctx.Err()
217
- }
218
- }
215
+ // check if we already have an open connection first
216
+ conn := s.bestConnectionToPeer(p)
217
+ if conn != nil {
218
+ return conn, nil
219
+ }
220
221
+ // check if there's an ongoing dial to this peer
222
+ if ok, wait := s.dsync.Lock(p); ok {
223
// ok, we have been charged to dial! let's do it.
224
// if it succeeds, dial will add the conn to the swarm itself.
222
- log.Debugf("dial start")
225
+
226
+ defer log.EventBegin(ctx, "swarmDialAttemptStart", logdial).Done()
227
ctxT, _ := context.WithTimeout(ctx, s.dialT)
224
- conn, err = s.dial(ctxT, p)
228
+ conn, err := s.dial(ctxT, p)
229
s.dsync.Unlock(p)
230
log.Debugf("dial end %s", conn)
231
if err != nil {
232
+ log.Event(ctx, "swarmDialBackoffAdd", logdial)
233
s.backf.AddBackoff(p) // let others know to backoff
234
230
- continue // ok, we failed. try again. (if loop is done, our error is output)
235
+ return nil, ErrDialFailed // ok, we failed. try again. (if loop is done, our error is output)
236
}
237
+ log.Event(ctx, "swarmDialBackoffClear", logdial)
238
s.backf.Clear(p) // okay, no longer need to backoff
239
return conn, nil
240
+
241
+ } else {
242
+ // we did not dial. we must wait for someone else to dial.
243
+
244
+ // check whether we should backoff first...
245
+ if s.backf.Backoff(p) {
246
+ log.Event(ctx, "swarmDialBackoff", logdial)
247
+ return nil, ErrDialBackoff
248
+ }
249
+
250
+ defer log.EventBegin(ctx, "swarmDialWait", logdial).Done()
251
+ select {
252
+ case <-wait: // wait for that other dial to finish.
253
+
254
+ // see if it worked, OR we got an incoming dial in the meantime...
255
+ conn := s.bestConnectionToPeer(p)
256
+ if conn != nil {
257
+ return conn, nil
258
+ }
259
+ return nil, ErrDialFailed
260
+ case <-ctx.Done(): // or we may have to bail...
261
+ return nil, ctx.Err()
262
+ }
263
}
235
- if err == nil {
236
- err = fmt.Errorf("%s failed to dial %s after %d attempts", s.local, p, dialAttempts)
237
- }
238
- return nil, err
264
}
265
266
// dial is the actual swarm's dial logic, gated by Dial.
267
func (s *Swarm) dial(ctx context.Context, p peer.ID) (*Conn, error) {
268
+ var logdial = lgbl.Dial("swarm", s.LocalPeer(), p, nil, nil)
269
+ defer log.EventBegin(ctx, "swarmDialDo", logdial).Done()
270
if p == s.local {
244
- return nil, errors.New("Attempted connection to self!")
271
+ log.Event(ctx, "swarmDialDoDialSelf", logdial)
272
+ return nil, ErrDialToSelf
273
}
274
275
sk := s.peers.PrivKey(s.local)
276
if sk == nil {
249
- // may be fine for sk to be nil, just log a warning.
250
- log.Warning("Dial not given PrivateKey, so WILL NOT SECURE conn.")
277
+ // may be fine for sk to be nil, just log.
278
+ log.Debug("Dial not given PrivateKey, so WILL NOT SECURE conn.")
279
+ log.Event(ctx, "swarmDialDoInsecure", logdial)
280
}
281
282
// get our own addrs. try dialing out from our listener addresses (reusing ports)
@@ -291,15 +320,16 @@ func (s *Swarm) dial(ctx context.Context, p peer.ID) (*Conn, error) {
320
}
321
322
// ok try to setup the new connection.
323
+ defer log.EventBegin(ctx, "swarmDialDoSetup", logdial, lgbl.NetConn(connC)).Done()
324
swarmC, err := dialConnSetup(ctx, s, connC)
325
if err != nil {
326
log.Debug("Dial newConnSetup failed. disconnecting.")
297
- log.Event(ctx, "dialFailureDisconnect", lgbl.NetConn(connC), lgbl.Error(err))
327
+ log.Event(ctx, "swarmDialDoSetupFailed", logdial, lgbl.NetConn(connC), lgbl.Error(err))
328
connC.Close() // close the connection. didn't work out :(
329
return nil, err
330
}
331
302
- log.Event(ctx, "dial", p)
332
+ log.Event(ctx, "swarmDialDoSuccess", logdial, lgbl.NetConn(connC))
333
return swarmC, nil
334
}
335
util/eventlog/loggables/loggables.go
+22
@@ -9,7 +9,11 @@ package loggables
9
import (
10
"net"
11
12
+ ma "github.com/jbenet/go-ipfs/Godeps/_workspace/src/github.com/jbenet/go-multiaddr"
13
+
14
log "github.com/jbenet/go-ipfs/thirdparty/eventlog"
15
+
16
+ peer "github.com/jbenet/go-ipfs/p2p/peer"
17
)
18
19
// NetConn returns an eventlog.Metadata with the conn addresses
@@ -26,3 +30,21 @@ func Error(e error) log.Loggable {
30
"error": e.Error(),
31
}
32
}
33
+
34
+// Dial metadata is metadata for dial events
35
+func Dial(sys string, lid, rid peer.ID, laddr, raddr ma.Multiaddr) log.LoggableMap {
36
+ m := log.Metadata{"subsystem": sys}
37
+ if lid != "" {
38
+ m["localPeer"] = lid.Pretty()
39
+ }
40
+ if laddr != nil {
41
+ m["localAddr"] = laddr.String()
42
+ }
43
+ if rid != "" {
44
+ m["remotePeer"] = rid.Pretty()
45
+ }
46
+ if raddr != nil {
47
+ m["remoteAddr"] = raddr.String()
48
+ }
49
+ return log.LoggableMap(m)
50
+}