From fd4b75cfa8e1b5de9eba9ea4dc89cfe3bb291a91 Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Wed, 6 May 2015 22:58:03 +0200 Subject: [PATCH 1/4] p2p/nat: less confusing error logging --- p2p/nat/nat.go | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/p2p/nat/nat.go b/p2p/nat/nat.go index 4ae7e6b172..fe00bdab0d 100644 --- a/p2p/nat/nat.go +++ b/p2p/nat/nat.go @@ -91,7 +91,8 @@ func Map(m Interface, c chan struct{}, protocol string, extport, intport int, na }() glog.V(logger.Debug).Infof("add mapping: %s %d -> %d (%s) using %s\n", protocol, extport, intport, name, m) if err := m.AddMapping(protocol, intport, extport, name, mapTimeout); err != nil { - glog.V(logger.Error).Infof("mapping error: %v\n", err) + glog.V(logger.Warn).Infof("network port %d could not be mapped: %v\n", intport, err) + glog.V(logger.Debug).Infof("mapping with %v returned %v\n", m, err) } for { select { @@ -102,7 +103,8 @@ func Map(m Interface, c chan struct{}, protocol string, extport, intport int, na case <-refresh.C: glog.V(logger.Detail).Infof("refresh mapping: %s %d -> %d (%s) using %s\n", protocol, extport, intport, name, m) if err := m.AddMapping(protocol, intport, extport, name, mapTimeout); err != nil { - glog.V(logger.Error).Infof("mapping error: %v\n", err) + glog.V(logger.Warn).Infof("network port %d could not be mapped: %v\n", intport, err) + glog.V(logger.Debug).Infof("mapping with %v returned %v\n", m, err) } refresh.Reset(mapUpdateInterval) } @@ -225,7 +227,7 @@ func (n *autodisc) wait() error { return nil } if found = <-n.done; found == nil { - return errors.New("no devices discovered") + return errors.New("no UPnP or NAT-PMP router discovered") } n.mu.Lock() n.found = found From bcfd7886619c9bc16f523f89ddd012cb53aa7159 Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Wed, 6 May 2015 22:59:00 +0200 Subject: [PATCH 2/4] p2p/discover: bump packet timeouts to 500ms --- p2p/discover/udp.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/p2p/discover/udp.go b/p2p/discover/udp.go index 7213325da8..1213c12c82 100644 --- a/p2p/discover/udp.go +++ b/p2p/discover/udp.go @@ -31,8 +31,8 @@ var ( // Timeouts const ( - respTimeout = 300 * time.Millisecond - sendTimeout = 300 * time.Millisecond + respTimeout = 500 * time.Millisecond + sendTimeout = 500 * time.Millisecond expiration = 20 * time.Second refreshInterval = 1 * time.Hour From 6a2fec5309e14df6b5fcd0fb76d5b123565d40d4 Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Wed, 6 May 2015 23:19:14 +0200 Subject: [PATCH 3/4] p2p, whisper: use glog for peer-level logging --- p2p/peer.go | 21 ++++++++------------- whisper/peer.go | 11 ++++++----- whisper/whisper.go | 4 ++-- 3 files changed, 16 insertions(+), 20 deletions(-) diff --git a/p2p/peer.go b/p2p/peer.go index 94fa03f8d3..cdf9ba9652 100644 --- a/p2p/peer.go +++ b/p2p/peer.go @@ -10,6 +10,7 @@ import ( "time" "github.com/ethereum/go-ethereum/logger" + "github.com/ethereum/go-ethereum/logger/glog" "github.com/ethereum/go-ethereum/p2p/discover" "github.com/ethereum/go-ethereum/rlp" ) @@ -34,10 +35,6 @@ const ( // Peer represents a connected remote node. type Peer struct { - // Peers have all the log methods. - // Use them to display messages related to the peer. - *logger.Logger - conn net.Conn rw *conn running map[string]*protoRW @@ -99,10 +96,8 @@ func (p *Peer) String() string { } func newPeer(fd net.Conn, conn *conn, protocols []Protocol) *Peer { - logtag := fmt.Sprintf("Peer %.8x %v", conn.ID[:], fd.RemoteAddr()) protomap := matchProtocols(protocols, conn.Caps, conn) p := &Peer{ - Logger: logger.NewLogger(logtag), conn: fd, rw: conn, running: protomap, @@ -130,7 +125,7 @@ func (p *Peer) run() DiscReason { } else { // Note: We rely on protocols to abort if there is a write // error. It might be more robust to handle them here as well. - p.DebugDetailf("Read error: %v\n", err) + glog.V(logger.Detail).Infof("%v: Read error: %v\n", p, err) reason = DiscNetworkError } case err := <-p.protoErr: @@ -141,7 +136,7 @@ func (p *Peer) run() DiscReason { close(p.closed) p.politeDisconnect(reason) p.wg.Wait() - p.Debugf("Disconnected: %v\n", reason) + glog.V(logger.Debug).Infof("%v: Disconnected: %v\n", p, reason) return reason } @@ -195,7 +190,7 @@ func (p *Peer) handle(msg Msg) error { // This is the last message. We don't need to discard or // check errors because, the connection will be closed after it. rlp.Decode(msg.Payload, &reason) - p.Debugf("Disconnect requested: %v\n", reason[0]) + glog.V(logger.Debug).Infof("%v: Disconnect Requested: %v\n", p, reason[0]) return DiscRequested case msg.Code < baseProtocolLength: // ignore other base protocol messages @@ -239,14 +234,14 @@ func (p *Peer) startProtocols() { for _, proto := range p.running { proto := proto proto.closed = p.closed - p.DebugDetailf("Starting protocol %s/%d\n", proto.Name, proto.Version) + glog.V(logger.Detail).Infof("%v: Starting protocol %s/%d\n", p, proto.Name, proto.Version) go func() { err := proto.Run(p, proto) if err == nil { - p.DebugDetailf("Protocol %s/%d returned\n", proto.Name, proto.Version) + glog.V(logger.Detail).Infof("%v: Protocol %s/%d returned\n", p, proto.Name, proto.Version) err = errors.New("protocol returned") - } else { - p.DebugDetailf("Protocol %s/%d error: %v\n", proto.Name, proto.Version, err) + } else if err != io.EOF { + glog.V(logger.Detail).Infof("%v: Protocol %s/%d error: \n", p, proto.Name, proto.Version, err) } p.protoErr <- err p.wg.Done() diff --git a/whisper/peer.go b/whisper/peer.go index 9fdc284346..0d9538ffc1 100644 --- a/whisper/peer.go +++ b/whisper/peer.go @@ -5,6 +5,8 @@ import ( "time" "github.com/ethereum/go-ethereum/common" + "github.com/ethereum/go-ethereum/logger" + "github.com/ethereum/go-ethereum/logger/glog" "github.com/ethereum/go-ethereum/p2p" "github.com/ethereum/go-ethereum/rlp" "gopkg.in/fatih/set.v0" @@ -36,13 +38,13 @@ func newPeer(host *Whisper, remote *p2p.Peer, rw p2p.MsgReadWriter) *peer { // into the network. func (self *peer) start() { go self.update() - self.peer.Debugln("whisper started") + glog.V(logger.Debug).Infof("%v: whisper started", self.peer) } // stop terminates the peer updater, stopping message forwarding to it. func (self *peer) stop() { close(self.quit) - self.peer.Debugln("whisper stopped") + glog.V(logger.Debug).Infof("%v: whisper stopped", self.peer) } // handshake sends the protocol initiation status message to the remote peer and @@ -94,7 +96,7 @@ func (self *peer) update() { case <-transmit.C: if err := self.broadcast(); err != nil { - self.peer.Infoln("broadcast failed:", err) + glog.V(logger.Info).Infof("%v: broadcast failed: %v", self.peer, err) return } @@ -152,7 +154,6 @@ func (self *peer) broadcast() error { if err := p2p.Send(self.ws, messagesCode, transmit); err != nil { return err } - self.peer.DebugDetailln("broadcasted", len(transmit), "message(s)") - + glog.V(logger.Detail).Infoln(self.peer, "broadcasted", len(transmit), "message(s)") return nil } diff --git a/whisper/whisper.go b/whisper/whisper.go index a48e1e380d..994b4e5069 100644 --- a/whisper/whisper.go +++ b/whisper/whisper.go @@ -197,14 +197,14 @@ func (self *Whisper) handlePeer(peer *p2p.Peer, rw p2p.MsgReadWriter) error { } var envelopes []*Envelope if err := packet.Decode(&envelopes); err != nil { - peer.Infof("failed to decode enveloped: %v", err) + glog.V(logger.Info).Infof("%v: failed to decode envelope: %v", peer, err) continue } // Inject all envelopes into the internal pool for _, envelope := range envelopes { if err := self.add(envelope); err != nil { // TODO Punish peer here. Invalid envelope. - peer.Debugf("failed to pool envelope: %f", err) + glog.V(logger.Debug).Infof("%v: failed to pool envelope: %v", peer, err) } whisperPeer.mark(envelope) } From 3e2a928caa74e523f43e14eec9918033ac1cbe0a Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Wed, 6 May 2015 23:44:51 +0200 Subject: [PATCH 4/4] p2p: stop dialing at half the maximum peer count --- p2p/server.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/p2p/server.go b/p2p/server.go index e648c72c97..98a2edd7c2 100644 --- a/p2p/server.go +++ b/p2p/server.go @@ -360,7 +360,7 @@ func (srv *Server) dialLoop() { case <-refresh.C: // Grab some nodes to connect to if we're not at capacity. srv.lock.RLock() - needpeers := len(srv.peers) < srv.MaxPeers + needpeers := len(srv.peers) < srv.MaxPeers/2 srv.lock.RUnlock() if needpeers { go func() {