Skip to content

Commit

Permalink
p2p, p2p/discover, p2p/nat: rework logging using context keys
Browse files Browse the repository at this point in the history
  • Loading branch information
@fjl
fjl committed Feb 28, 2017
1 parent 35e8308 commit 96ae35e
Show file tree
Hide file tree
Showing 11 changed files with 171 additions and 151 deletions.
13 changes: 6 additions & 7 deletions p2p/dial.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -133,7 +133,7 @@ func (s *dialstate) newTasks(nRunning int, peers map[discover.NodeID]*Peer, now
var newtasks []task
addDial := func(flag connFlag, n *discover.Node) bool {
if err := s.checkDial(n, peers); err != nil {
log.Debug(fmt.Sprintf("skipping dial candidate %x@%v:%d: %v", n.ID[:8], n.IP, n.TCP, err))
log.Trace("Skipping dial candidate", "id", n.ID, "addr", &net.TCPAddr{IP: n.IP, Port: int(n.TCP)}, "err", err)
return false
}
s.dialing[n.ID] = flag
Expand Down Expand Up @@ -162,7 +162,7 @@ func (s *dialstate) newTasks(nRunning int, peers map[discover.NodeID]*Peer, now
err := s.checkDial(t.dest, peers)
switch err {
case errNotWhitelisted, errSelf:
log.Debug(fmt.Sprintf("removing static dial candidate %x@%v:%d: %v", t.dest.ID[:8], t.dest.IP, t.dest.TCP, err))
log.Warn("Removing static dial candidate", "id", t.dest.ID, "addr", &net.TCPAddr{IP: t.dest.IP, Port: int(t.dest.TCP)}, "err", err)
delete(s.static, t.dest.ID)
case nil:
s.dialing[id] = t.flags
Expand Down Expand Up @@ -266,7 +266,7 @@ func (t *dialTask) Do(srv *Server) {
// The backoff delay resets when the node is found.
func (t *dialTask) resolve(srv *Server) bool {
if srv.ntab == nil {
log.Debug(fmt.Sprintf("can't resolve node %x: discovery is disabled", t.dest.ID[:6]))
log.Debug("Can't resolve node", "id", t.dest.ID, "err", "discovery is disabled")
return false
}
if t.resolveDelay == 0 {
Expand All @@ -282,23 +282,22 @@ func (t *dialTask) resolve(srv *Server) bool {
if t.resolveDelay > maxResolveDelay {
t.resolveDelay = maxResolveDelay
}
log.Debug(fmt.Sprintf("resolving node %x failed (new delay: %v)", t.dest.ID[:6], t.resolveDelay))
log.Debug("Resolving node failed", "id", t.dest.ID, "newdelay", t.resolveDelay)
return false
}
// The node was found.
t.resolveDelay = initialResolveDelay
t.dest = resolved
log.Debug(fmt.Sprintf("resolved node %x: %v:%d", t.dest.ID[:6], t.dest.IP, t.dest.TCP))
log.Debug("Resolved node", "id", t.dest.ID, "addr", &net.TCPAddr{IP: t.dest.IP, Port: int(t.dest.TCP)})
return true
}

// dial performs the actual connection attempt.
func (t *dialTask) dial(srv *Server, dest *discover.Node) bool {
addr := &net.TCPAddr{IP: dest.IP, Port: int(dest.TCP)}
log.Debug(fmt.Sprintf("dial tcp %v (%x)", addr, dest.ID[:6]))
fd, err := srv.Dialer.Dial("tcp", addr.String())
if err != nil {
log.Trace(fmt.Sprintf("%v", err))
log.Trace("Dial error", "task", t, "err", err)
return false
}
mfd := newMeteredConn(fd, false)
Expand Down
8 changes: 3 additions & 5 deletions p2p/discover/database.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -23,7 +23,6 @@ import (
"bytes"
"crypto/rand"
"encoding/binary"
"fmt"
"os"
"sync"
"time"
Expand Down Expand Up @@ -180,12 +179,11 @@ func (db *nodeDB) storeInt64(key []byte, n int64) error {
func (db *nodeDB) node(id NodeID) *Node {
blob, err := db.lvl.Get(makeKey(id, nodeDBDiscoverRoot), nil)
if err != nil {
log.Trace(fmt.Sprintf("failed to retrieve node %v: %v", id, err))
return nil
}
node := new(Node)
if err := rlp.DecodeBytes(blob, node); err != nil {
log.Warn(fmt.Sprintf("failed to decode node RLP: %v", err))
log.Error("Failed to decode node RLP", "err", err)
return nil
}
node.sha = crypto.Keccak256Hash(node.ID[:])
Expand Down Expand Up @@ -233,7 +231,7 @@ func (db *nodeDB) expirer() {
select {
case <-tick:
if err := db.expireNodes(); err != nil {
log.Error(fmt.Sprintf("Failed to expire nodedb items: %v", err))
log.Error("Failed to expire nodedb items", "err", err)
}

case <-db.quit:
Expand Down Expand Up @@ -352,7 +350,7 @@ func nextNode(it iterator.Iterator) *Node {
}
var n Node
if err := rlp.DecodeBytes(it.Value(), &n); err != nil {
log.Warn(fmt.Sprintf("invalid node %x: %v", id, err))
log.Warn("Failed to decode node RLP", "id", id, "err", err)
continue
}
return &n
Expand Down
5 changes: 5 additions & 0 deletions p2p/discover/node.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -221,6 +221,11 @@ func (n NodeID) GoString() string {
return fmt.Sprintf("discover.HexID(\"%x\")", n[:])
}

// TerminalString returns a shortened hex string for terminal logging.
func (n NodeID) TerminalString() string {
return hex.EncodeToString(n[:8])
}

// HexID converts a hex string to a NodeID.
// The string may be prefixed with 0x.
func HexID(in string) (NodeID, error) {
Expand Down
13 changes: 3 additions & 10 deletions p2p/discover/ntp.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -23,7 +23,6 @@ import (
"fmt"
"net"
"sort"
"strings"
"time"

"github.com/ethereum/go-ethereum/log"
Expand All @@ -50,16 +49,10 @@ func checkClockDrift() {
return
}
if drift < -driftThreshold || drift > driftThreshold {
warning := fmt.Sprintf("System clock seems off by %v, which can prevent network connectivity", drift)
howtofix := fmt.Sprintf("Please enable network time synchronisation in system settings")
separator := strings.Repeat("-", len(warning))

log.Warn(fmt.Sprint(separator))
log.Warn(fmt.Sprint(warning))
log.Warn(fmt.Sprint(howtofix))
log.Warn(fmt.Sprint(separator))
log.Warn(fmt.Sprintf("System clock seems off by %v, which can prevent network connectivity", drift))
log.Warn("Please enable network time synchronisation in system settings.")
} else {
log.Debug(fmt.Sprintf("Sanity NTP check reported %v drift, all ok", drift))
log.Debug("NTP sanity check done", "drift", drift)
}
}

Expand Down
14 changes: 6 additions & 8 deletions p2p/discover/table.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -277,10 +277,10 @@ func (tab *Table) lookup(targetID NodeID, refreshIfEmpty bool) []*Node {
// Bump the failure counter to detect and evacuate non-bonded entries
fails := tab.db.findFails(n.ID) + 1
tab.db.updateFindFails(n.ID, fails)
log.Trace(fmt.Sprintf("Bumping failures for %x: %d", n.ID[:8], fails))
log.Trace("Bumping findnode failure counter", "id", n.ID, "failcount", fails)

if fails >= maxFindnodeFailures {
log.Trace(fmt.Sprintf("Evacuating node %x: %d findnode failures", n.ID[:8], fails))
log.Trace("Too many findnode failures, dropping", "id", n.ID, "failcount", fails)
tab.delete(n)
}
}
Expand Down Expand Up @@ -385,13 +385,11 @@ func (tab *Table) doRefresh(done chan struct{}) {
seeds = tab.bondall(append(seeds, tab.nursery...))

if len(seeds) == 0 {
log.Debug(fmt.Sprintf("no seed nodes found"))
log.Debug("No discv4 seed nodes found")
}
for _, n := range seeds {
log.Debug("", "msg", log.Lazy{Fn: func() string {
age := time.Since(tab.db.lastPong(n.ID))
return fmt.Sprintf("seed node (age %v): %v", age, n)
}})
age := log.Lazy{Fn: func() time.Duration { return time.Since(tab.db.lastPong(n.ID)) }}
log.Trace("Found seed node in database", "id", n.ID, "addr", n.addr(), "age", age)
}
tab.mutex.Lock()
tab.stuff(seeds)
Expand Down Expand Up @@ -470,7 +468,7 @@ func (tab *Table) bond(pinged bool, id NodeID, addr *net.UDPAddr, tcpPort uint16
var result error
age := time.Since(tab.db.lastPong(id))
if node == nil || fails > 0 || age > nodeDBNodeExpiration {
log.Trace(fmt.Sprintf("Bonding %x: known=%t, fails=%d age=%v", id[:8], node != nil, fails, age))
log.Trace("Starting bonding ping/pong", "id", id, "known", node != nil, "failcount", fails, "age", age)

tab.bondmu.Lock()
w := tab.bonding[id]
Expand Down
46 changes: 25 additions & 21 deletions p2p/discover/udp.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -147,6 +147,7 @@ func nodeToRPC(n *Node) rpcNode {

type packet interface {
handle(t *udp, from *net.UDPAddr, fromID NodeID, mac []byte) error
name() string
}

type conn interface {
Expand Down Expand Up @@ -223,7 +224,7 @@ func ListenUDP(priv *ecdsa.PrivateKey, laddr string, natm nat.Interface, nodeDBP
if err != nil {
return nil, err
}
log.Info(fmt.Sprint("Listening,", tab.self))
log.Debug("UDP listener up", "self", tab.self)
return tab, nil
}

Expand Down Expand Up @@ -269,7 +270,7 @@ func (t *udp) close() {
func (t *udp) ping(toid NodeID, toaddr *net.UDPAddr) error {
// TODO: maybe check for ReplyTo field in callback to measure RTT
errc := t.pending(toid, pongPacket, func(interface{}) bool { return true })
t.send(toaddr, pingPacket, ping{
t.send(toaddr, pingPacket, &ping{
Version: Version,
From: t.ourEndpoint,
To: makeEndpoint(toaddr, 0), // TODO: maybe use known TCP port from DB
Expand All @@ -293,14 +294,14 @@ func (t *udp) findnode(toid NodeID, toaddr *net.UDPAddr, target NodeID) ([]*Node
nreceived++
n, err := t.nodeFromRPC(toaddr, rn)
if err != nil {
log.Trace(fmt.Sprintf("invalid neighbor node (%v) from %v: %v", rn.IP, toaddr, err))
log.Trace("Invalid neighbor node received", "ip", rn.IP, "addr", toaddr, "err", err)
continue
}
nodes = append(nodes, n)
}
return nreceived >= bucketSize
})
t.send(toaddr, findnodePacket, findnode{
t.send(toaddr, findnodePacket, &findnode{
Target: target,
Expiration: uint64(time.Now().Add(expiration).Unix()),
})
Expand Down Expand Up @@ -458,15 +459,13 @@ func init() {
}
}

func (t *udp) send(toaddr *net.UDPAddr, ptype byte, req interface{}) error {
func (t *udp) send(toaddr *net.UDPAddr, ptype byte, req packet) error {
packet, err := encodePacket(t.priv, ptype, req)
if err != nil {
return err
}
log.Trace(fmt.Sprintf(">>> %v %T", toaddr, req))
if _, err = t.conn.WriteToUDP(packet, toaddr); err != nil {
log.Trace(fmt.Sprint("UDP send failed:", err))
}
_, err = t.conn.WriteToUDP(packet, toaddr)
log.Trace(">> "+req.name(), "addr", toaddr, "err", err)
return err
}

Expand All @@ -475,13 +474,13 @@ func encodePacket(priv *ecdsa.PrivateKey, ptype byte, req interface{}) ([]byte,
b.Write(headSpace)
b.WriteByte(ptype)
if err := rlp.Encode(b, req); err != nil {
log.Error(fmt.Sprint("error encoding packet:", err))
log.Error("Can't encode discv4 packet", "err", err)
return nil, err
}
packet := b.Bytes()
sig, err := crypto.Sign(crypto.Keccak256(packet[headSize:]), priv)
if err != nil {
log.Error(fmt.Sprint("could not sign packet:", err))
log.Error("Can't sign discv4 packet", "err", err)
return nil, err
}
copy(packet[macSize:], sig)
Expand All @@ -503,11 +502,11 @@ func (t *udp) readLoop() {
nbytes, from, err := t.conn.ReadFromUDP(buf)
if netutil.IsTemporaryError(err) {
// Ignore temporary read errors.
log.Debug(fmt.Sprintf("Temporary read error: %v", err))
log.Debug("Temporary UDP read error", "err", err)
continue
} else if err != nil {
// Shut down the loop for permament errors.
log.Debug(fmt.Sprintf("Read error: %v", err))
log.Debug("UDP read error", "err", err)
return
}
t.handlePacket(from, buf[:nbytes])
Expand All @@ -517,14 +516,11 @@ func (t *udp) readLoop() {
func (t *udp) handlePacket(from *net.UDPAddr, buf []byte) error {
packet, fromID, hash, err := decodePacket(buf)
if err != nil {
log.Debug(fmt.Sprintf("Bad packet from %v: %v", from, err))
log.Debug("Bad discv4 packet", "addr", from, "err", err)
return err
}
status := "ok"
if err = packet.handle(t, from, fromID, hash); err != nil {
status = err.Error()
}
log.Trace(fmt.Sprintf("<<< %v %T: %s", from, packet, status))
err = packet.handle(t, from, fromID, hash)
log.Trace("<< "+packet.name(), "addr", from, "err", err)
return err
}

Expand Down Expand Up @@ -563,7 +559,7 @@ func (req *ping) handle(t *udp, from *net.UDPAddr, fromID NodeID, mac []byte) er
if expired(req.Expiration) {
return errExpired
}
t.send(from, pongPacket, pong{
t.send(from, pongPacket, &pong{
To: makeEndpoint(from, req.From.TCP),
ReplyTok: mac,
Expiration: uint64(time.Now().Add(expiration).Unix()),
Expand All @@ -575,6 +571,8 @@ func (req *ping) handle(t *udp, from *net.UDPAddr, fromID NodeID, mac []byte) er
return nil
}

func (req *ping) name() string { return "PING/v4" }

func (req *pong) handle(t *udp, from *net.UDPAddr, fromID NodeID, mac []byte) error {
if expired(req.Expiration) {
return errExpired
Expand All @@ -585,6 +583,8 @@ func (req *pong) handle(t *udp, from *net.UDPAddr, fromID NodeID, mac []byte) er
return nil
}

func (req *pong) name() string { return "PONG/v4" }

func (req *findnode) handle(t *udp, from *net.UDPAddr, fromID NodeID, mac []byte) error {
if expired(req.Expiration) {
return errExpired
Expand Down Expand Up @@ -613,13 +613,15 @@ func (req *findnode) handle(t *udp, from *net.UDPAddr, fromID NodeID, mac []byte
}
p.Nodes = append(p.Nodes, nodeToRPC(n))
if len(p.Nodes) == maxNeighbors || i == len(closest)-1 {
t.send(from, neighborsPacket, p)
t.send(from, neighborsPacket, &p)
p.Nodes = p.Nodes[:0]
}
}
return nil
}

func (req *findnode) name() string { return "FINDNODE/v4" }

func (req *neighbors) handle(t *udp, from *net.UDPAddr, fromID NodeID, mac []byte) error {
if expired(req.Expiration) {
return errExpired
Expand All @@ -630,6 +632,8 @@ func (req *neighbors) handle(t *udp, from *net.UDPAddr, fromID NodeID, mac []byt
return nil
}

func (req *neighbors) name() string { return "NEIGHBORS/v4" }

func expired(ts uint64) bool {
return time.Unix(int64(ts), 0).Before(time.Now())
}
11 changes: 6 additions & 5 deletions p2p/nat/nat.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -98,16 +98,17 @@ const (
// Map adds a port mapping on m and keeps it alive until c is closed.
// This function is typically invoked in its own goroutine.
func Map(m Interface, c chan struct{}, protocol string, extport, intport int, name string) {
log := log.New("proto", protocol, "extport", extport, "intport", intport, "interface", m)
refresh := time.NewTimer(mapUpdateInterval)
defer func() {
refresh.Stop()
log.Debug(fmt.Sprintf("deleting port mapping: %s %d -> %d (%s) using %s", protocol, extport, intport, name, m))
log.Debug("Deleting port mapping")
m.DeleteMapping(protocol, extport, intport)
}()
if err := m.AddMapping(protocol, extport, intport, name, mapTimeout); err != nil {
log.Debug(fmt.Sprintf("network port %s:%d could not be mapped: %v", protocol, intport, err))
log.Debug("Couldn't add port mapping", "err", err)
} else {
log.Info(fmt.Sprintf("mapped network port %s:%d -> %d (%s) using %s", protocol, extport, intport, name, m))
log.Info("Mapped network port")
}
for {
select {
Expand All @@ -116,9 +117,9 @@ func Map(m Interface, c chan struct{}, protocol string, extport, intport int, na
return
}
case <-refresh.C:
log.Trace(fmt.Sprintf("refresh port mapping %s:%d -> %d (%s) using %s", protocol, extport, intport, name, m))
log.Trace("Refreshing port mapping")
if err := m.AddMapping(protocol, extport, intport, name, mapTimeout); err != nil {
log.Debug(fmt.Sprintf("network port %s:%d could not be mapped: %v", protocol, intport, err))
log.Debug("Couldn't add port mapping", "err", err)
}
refresh.Reset(mapUpdateInterval)
}
Expand Down
Loading

0 comments on commit 96ae35e

Please sign in to comment.