diff --git a/p2p/dial.go b/p2p/dial.go index 09badc97a1..d8436eb201 100644 --- a/p2p/dial.go +++ b/p2p/dial.go @@ -39,6 +39,10 @@ const ( // private networks. dialHistoryExpiration = inboundThrottleTime + 5*time.Second + // Config for the "Looking for peers" message. + dialStatsLogInterval = 10 * time.Second // printed at most this often + dialStatsPeerLimit = 3 // but not if more than this many dialed peers + // Endpoint resolution is throttled with bounded backoff. initialResolveDelay = 60 * time.Second maxResolveDelay = time.Hour @@ -113,6 +117,10 @@ type dialScheduler struct { history expHeap historyTimer mclock.Timer historyTimerTime mclock.AbsTime + + // for logStats + lastStatsLog mclock.AbsTime + doneSinceLastLog int } type dialSetupFunc func(net.Conn, connFlag, *enode.Node) error @@ -162,6 +170,7 @@ func newDialScheduler(config dialConfig, it enode.Iterator, setupFunc dialSetupF addPeerCh: make(chan *conn), remPeerCh: make(chan *conn), } + d.lastStatsLog = d.clock.Now() d.ctx, d.cancel = context.WithCancel(context.Background()) d.wg.Add(2) go d.readNodes(it) @@ -225,6 +234,7 @@ loop: nodesCh = nil } d.rearmHistoryTimer(historyExp) + d.logStats() select { case node := <-nodesCh: @@ -238,6 +248,7 @@ loop: id := task.dest.ID() delete(d.dialing, id) d.updateStaticPool(id) + d.doneSinceLastLog++ case c := <-d.addPeerCh: if c.is(dynDialedConn) || c.is(staticDialedConn) { @@ -312,6 +323,21 @@ func (d *dialScheduler) readNodes(it enode.Iterator) { } } +// logStats prints dialer statistics to the log. The message is suppressed when enough +// peers are connected because users should only see it while their client is starting up +// or comes back online. +func (d *dialScheduler) logStats() { + now := d.clock.Now() + if d.lastStatsLog.Add(dialStatsLogInterval) > now { + return + } + if d.dialPeers < dialStatsPeerLimit && d.dialPeers < d.maxDialPeers { + d.log.Info("Looking for peers", "peercount", len(d.peers), "tried", d.doneSinceLastLog, "static", len(d.static)) + } + d.doneSinceLastLog = 0 + d.lastStatsLog = now +} + // rearmHistoryTimer configures d.historyTimer to fire when the // next item in d.history expires. func (d *dialScheduler) rearmHistoryTimer(ch chan struct{}) { diff --git a/p2p/server.go b/p2p/server.go index 309ff6ae02..049b2df44a 100644 --- a/p2p/server.go +++ b/p2p/server.go @@ -726,7 +726,7 @@ running: // The handshakes are done and it passed all checks. p := srv.launchPeer(c) peers[c.node.ID()] = p - p.log.Debug("Adding p2p peer", "addr", p.RemoteAddr(), "peers", len(peers), "name", truncateName(c.name)) + srv.log.Debug("Adding p2p peer", "peercount", len(peers), "id", p.ID(), "conn", c.flags, "addr", p.RemoteAddr(), "name", truncateName(c.name)) srv.dialsched.peerAdded(c) if conn, ok := c.fd.(*meteredConn); ok { conn.handshakeDone(p) @@ -741,7 +741,7 @@ running: // A peer disconnected. d := common.PrettyDuration(mclock.Now() - pd.created) delete(peers, pd.ID()) - pd.log.Debug("Removing p2p peer", "addr", pd.RemoteAddr(), "peers", len(peers), "duration", d, "req", pd.requested, "err", pd.err) + srv.log.Debug("Removing p2p peer", "peercount", len(peers), "id", pd.ID(), "duration", d, "req", pd.requested, "err", pd.err) srv.dialsched.peerRemoved(pd.rw) if pd.Inbound() { inboundCount--