p2p: fix dialer tests

This change also makes the dialer use the server log and configures unit
test logging for dialer tests.
This commit is contained in:
Felix Lange 2019-06-11 12:05:14 +02:00
parent 28bd3e8bf0
commit 34870ae606
3 changed files with 88 additions and 62 deletions

View file

@ -72,16 +72,16 @@ type dialstate struct {
ntab discoverTable
netrestrict *netutil.Netlist
self enode.ID
bootnodes []*enode.Node // default dials when there are no peers
log log.Logger
start time.Time // time when the dialer was first used
lookupRunning bool
dialing map[enode.ID]connFlag
lookupBuf []*enode.Node // current discovery lookup results
randomNodes []*enode.Node // filled from Table
static map[enode.ID]*dialTask
hist expHeap
start time.Time // time when the dialer was first used
bootnodes []*enode.Node // default dials when there are no peers
}
type discoverTable interface {
@ -117,19 +117,23 @@ type waitExpireTask struct {
time.Duration
}
func newDialState(self enode.ID, static []*enode.Node, bootnodes []*enode.Node, ntab discoverTable, maxdyn int, netrestrict *netutil.Netlist) *dialstate {
func newDialState(self enode.ID, ntab discoverTable, maxdyn int, cfg *Config) *dialstate {
s := &dialstate{
maxDynDials: maxdyn,
ntab: ntab,
self: self,
netrestrict: netrestrict,
netrestrict: cfg.NetRestrict,
log: cfg.Logger,
static: make(map[enode.ID]*dialTask),
dialing: make(map[enode.ID]connFlag),
bootnodes: make([]*enode.Node, len(bootnodes)),
bootnodes: make([]*enode.Node, len(cfg.BootstrapNodes)),
randomNodes: make([]*enode.Node, maxdyn/2),
}
copy(s.bootnodes, bootnodes)
for _, n := range static {
copy(s.bootnodes, cfg.BootstrapNodes)
if s.log == nil {
s.log = log.Root()
}
for _, n := range cfg.StaticNodes {
s.addStatic(n)
}
return s
@ -154,7 +158,7 @@ func (s *dialstate) newTasks(nRunning int, peers map[enode.ID]*Peer, now time.Ti
var newtasks []task
addDial := func(flag connFlag, n *enode.Node) bool {
if err := s.checkDial(n, peers); err != nil {
log.Trace("Skipping dial candidate", "id", n.ID(), "addr", &net.TCPAddr{IP: n.IP(), Port: n.TCP()}, "err", err)
s.log.Trace("Skipping dial candidate", "id", n.ID(), "addr", &net.TCPAddr{IP: n.IP(), Port: n.TCP()}, "err", err)
return false
}
s.dialing[n.ID()] = flag
@ -183,7 +187,7 @@ func (s *dialstate) newTasks(nRunning int, peers map[enode.ID]*Peer, now time.Ti
err := s.checkDial(t.dest, peers)
switch err {
case errNotWhitelisted, errSelf:
log.Warn("Removing static dial candidate", "id", t.dest.ID, "addr", &net.TCPAddr{IP: t.dest.IP(), Port: t.dest.TCP()}, "err", err)
s.log.Warn("Removing static dial candidate", "id", t.dest.ID, "addr", &net.TCPAddr{IP: t.dest.IP(), Port: t.dest.TCP()}, "err", err)
delete(s.static, t.dest.ID())
case nil:
s.dialing[id] = t.flags
@ -283,7 +287,7 @@ func (t *dialTask) Do(srv *Server) {
}
err := t.dial(srv, t.dest)
if err != nil {
log.Trace("Dial error", "task", t, "err", err)
srv.log.Trace("Dial error", "task", t, "err", err)
// Try resolving the ID of static nodes if dialing failed.
if _, ok := err.(*dialError); ok && t.flags&staticDialedConn != 0 {
if t.resolve(srv) {
@ -301,7 +305,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("Can't resolve node", "id", t.dest.ID, "err", "discovery is disabled")
srv.log.Debug("Can't resolve node", "id", t.dest.ID, "err", "discovery is disabled")
return false
}
if t.resolveDelay == 0 {
@ -317,13 +321,13 @@ func (t *dialTask) resolve(srv *Server) bool {
if t.resolveDelay > maxResolveDelay {
t.resolveDelay = maxResolveDelay
}
log.Debug("Resolving node failed", "id", t.dest.ID, "newdelay", t.resolveDelay)
srv.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("Resolved node", "id", t.dest.ID, "addr", &net.TCPAddr{IP: t.dest.IP(), Port: t.dest.TCP()})
srv.log.Debug("Resolved node", "id", t.dest.ID, "addr", &net.TCPAddr{IP: t.dest.IP(), Port: t.dest.TCP()})
return true
}

View file

@ -20,10 +20,13 @@ import (
"encoding/binary"
"net"
"reflect"
"strings"
"testing"
"time"
"github.com/davecgh/go-spew/spew"
"github.com/ethereum/go-ethereum/internal/testlog"
"github.com/ethereum/go-ethereum/log"
"github.com/ethereum/go-ethereum/p2p/enode"
"github.com/ethereum/go-ethereum/p2p/enr"
"github.com/ethereum/go-ethereum/p2p/netutil"
@ -67,10 +70,10 @@ func runDialTest(t *testing.T, test dialtest) {
new := test.init.newTasks(running, pm(round.peers), vtime)
if !sametasks(new, round.new) {
t.Errorf("round %d: new tasks mismatch:\ngot %v\nwant %v\nstate: %v\nrunning: %v\n",
t.Errorf("ERROR round %d: got %v\nwant %v\nstate: %v\nrunning: %v",
i, spew.Sdump(new), spew.Sdump(round.new), spew.Sdump(test.init), spew.Sdump(running))
}
t.Log("tasks:", spew.Sdump(new))
t.Logf("round %d new tasks: %s", i, strings.TrimSpace(spew.Sdump(new)))
// Time advances by 16 seconds on every round.
vtime = vtime.Add(16 * time.Second)
@ -88,8 +91,9 @@ func (t fakeTable) ReadRandomNodes(buf []*enode.Node) int { return copy(buf, t)
// This test checks that dynamic dials are launched from discovery results.
func TestDialStateDynDial(t *testing.T) {
config := &Config{Logger: testlog.Logger(t, log.LvlTrace)}
runDialTest(t, dialtest{
init: newDialState(enode.ID{}, nil, nil, fakeTable{}, 5, nil),
init: newDialState(enode.ID{}, fakeTable{}, 5, config),
rounds: []round{
// A discovery query is launched.
{
@ -153,7 +157,7 @@ func TestDialStateDynDial(t *testing.T) {
&dialTask{flags: dynDialedConn, dest: newNode(uintID(5), nil)},
},
new: []task{
&waitExpireTask{Duration: 14 * time.Second},
&waitExpireTask{Duration: 19 * time.Second},
},
},
// In this round, the peer with id 2 drops off. The query
@ -223,10 +227,13 @@ func TestDialStateDynDial(t *testing.T) {
// Tests that bootnodes are dialed if no peers are connectd, but not otherwise.
func TestDialStateDynDialBootnode(t *testing.T) {
bootnodes := []*enode.Node{
config := &Config{
BootstrapNodes: []*enode.Node{
newNode(uintID(1), nil),
newNode(uintID(2), nil),
newNode(uintID(3), nil),
},
Logger: testlog.Logger(t, log.LvlTrace),
}
table := fakeTable{
newNode(uintID(4), nil),
@ -236,7 +243,7 @@ func TestDialStateDynDialBootnode(t *testing.T) {
newNode(uintID(8), nil),
}
runDialTest(t, dialtest{
init: newDialState(enode.ID{}, nil, bootnodes, table, 5, nil),
init: newDialState(enode.ID{}, table, 5, config),
rounds: []round{
// 2 dynamic dials attempted, bootnodes pending fallback interval
{
@ -259,25 +266,24 @@ func TestDialStateDynDialBootnode(t *testing.T) {
{
new: []task{
&dialTask{flags: dynDialedConn, dest: newNode(uintID(1), nil)},
&dialTask{flags: dynDialedConn, dest: newNode(uintID(4), nil)},
&dialTask{flags: dynDialedConn, dest: newNode(uintID(5), nil)},
},
},
// No dials succeed, 2nd bootnode is attempted
{
done: []task{
&dialTask{flags: dynDialedConn, dest: newNode(uintID(1), nil)},
&dialTask{flags: dynDialedConn, dest: newNode(uintID(4), nil)},
&dialTask{flags: dynDialedConn, dest: newNode(uintID(5), nil)},
},
new: []task{
&dialTask{flags: dynDialedConn, dest: newNode(uintID(2), nil)},
&dialTask{flags: dynDialedConn, dest: newNode(uintID(4), nil)},
&dialTask{flags: dynDialedConn, dest: newNode(uintID(5), nil)},
},
},
// No dials succeed, 3rd bootnode is attempted
{
done: []task{
&dialTask{flags: dynDialedConn, dest: newNode(uintID(2), nil)},
&dialTask{flags: dynDialedConn, dest: newNode(uintID(5), nil)},
},
new: []task{
&dialTask{flags: dynDialedConn, dest: newNode(uintID(3), nil)},
@ -288,21 +294,19 @@ func TestDialStateDynDialBootnode(t *testing.T) {
done: []task{
&dialTask{flags: dynDialedConn, dest: newNode(uintID(3), nil)},
},
new: []task{
&dialTask{flags: dynDialedConn, dest: newNode(uintID(1), nil)},
&dialTask{flags: dynDialedConn, dest: newNode(uintID(4), nil)},
&dialTask{flags: dynDialedConn, dest: newNode(uintID(5), nil)},
},
new: []task{},
},
// Random dial succeeds, no more bootnodes are attempted
{
new: []task{
&waitExpireTask{3 * time.Second},
},
peers: []*Peer{
{rw: &conn{flags: dynDialedConn, node: newNode(uintID(4), nil)}},
},
done: []task{
&dialTask{flags: dynDialedConn, dest: newNode(uintID(1), nil)},
&dialTask{flags: dynDialedConn, dest: newNode(uintID(4), nil)},
&dialTask{flags: dynDialedConn, dest: newNode(uintID(5), nil)},
},
},
},
@ -324,7 +328,7 @@ func TestDialStateDynDialFromTable(t *testing.T) {
}
runDialTest(t, dialtest{
init: newDialState(enode.ID{}, nil, nil, table, 10, nil),
init: newDialState(enode.ID{}, table, 10, &Config{Logger: testlog.Logger(t, log.LvlTrace)}),
rounds: []round{
// 5 out of 8 of the nodes returned by ReadRandomNodes are dialed.
{
@ -430,7 +434,7 @@ func TestDialStateNetRestrict(t *testing.T) {
restrict.Add("127.0.2.0/24")
runDialTest(t, dialtest{
init: newDialState(enode.ID{}, nil, nil, table, 10, restrict),
init: newDialState(enode.ID{}, table, 10, &Config{NetRestrict: restrict}),
rounds: []round{
{
new: []task{
@ -444,16 +448,18 @@ func TestDialStateNetRestrict(t *testing.T) {
// This test checks that static dials are launched.
func TestDialStateStaticDial(t *testing.T) {
wantStatic := []*enode.Node{
config := &Config{
StaticNodes: []*enode.Node{
newNode(uintID(1), nil),
newNode(uintID(2), nil),
newNode(uintID(3), nil),
newNode(uintID(4), nil),
newNode(uintID(5), nil),
},
Logger: testlog.Logger(t, log.LvlTrace),
}
runDialTest(t, dialtest{
init: newDialState(enode.ID{}, wantStatic, nil, fakeTable{}, 0, nil),
init: newDialState(enode.ID{}, fakeTable{}, 0, config),
rounds: []round{
// Static dials are launched for the nodes that
// aren't yet connected.
@ -495,7 +501,7 @@ func TestDialStateStaticDial(t *testing.T) {
&dialTask{flags: staticDialedConn, dest: newNode(uintID(5), nil)},
},
new: []task{
&waitExpireTask{Duration: 14 * time.Second},
&waitExpireTask{Duration: 19 * time.Second},
},
},
// Wait a round for dial history to expire, no new tasks should spawn.
@ -511,6 +517,9 @@ func TestDialStateStaticDial(t *testing.T) {
// If a static node is dropped, it should be immediately redialed,
// irrespective whether it was originally static or dynamic.
{
done: []task{
&waitExpireTask{Duration: 19 * time.Second},
},
peers: []*Peer{
{rw: &conn{flags: dynDialedConn, node: newNode(uintID(1), nil)}},
{rw: &conn{flags: staticDialedConn, node: newNode(uintID(3), nil)}},
@ -518,7 +527,6 @@ func TestDialStateStaticDial(t *testing.T) {
},
new: []task{
&dialTask{flags: staticDialedConn, dest: newNode(uintID(2), nil)},
&dialTask{flags: staticDialedConn, dest: newNode(uintID(4), nil)},
},
},
},
@ -527,14 +535,16 @@ func TestDialStateStaticDial(t *testing.T) {
// This test checks that past dials are not retried for some time.
func TestDialStateCache(t *testing.T) {
wantStatic := []*enode.Node{
config := &Config{
StaticNodes: []*enode.Node{
newNode(uintID(1), nil),
newNode(uintID(2), nil),
newNode(uintID(3), nil),
},
Logger: testlog.Logger(t, log.LvlTrace),
}
runDialTest(t, dialtest{
init: newDialState(enode.ID{}, wantStatic, nil, fakeTable{}, 0, nil),
init: newDialState(enode.ID{}, fakeTable{}, 0, config),
rounds: []round{
// Static dials are launched for the nodes that
// aren't yet connected.
@ -562,28 +572,37 @@ func TestDialStateCache(t *testing.T) {
// entry to expire.
{
peers: []*Peer{
{rw: &conn{flags: dynDialedConn, node: newNode(uintID(1), nil)}},
{rw: &conn{flags: dynDialedConn, node: newNode(uintID(2), nil)}},
{rw: &conn{flags: staticDialedConn, node: newNode(uintID(1), nil)}},
{rw: &conn{flags: staticDialedConn, node: newNode(uintID(2), nil)}},
},
done: []task{
&dialTask{flags: staticDialedConn, dest: newNode(uintID(3), nil)},
},
new: []task{
&waitExpireTask{Duration: 14 * time.Second},
&waitExpireTask{Duration: 19 * time.Second},
},
},
// Still waiting for node 3's entry to expire in the cache.
{
peers: []*Peer{
{rw: &conn{flags: dynDialedConn, node: newNode(uintID(1), nil)}},
{rw: &conn{flags: dynDialedConn, node: newNode(uintID(2), nil)}},
{rw: &conn{flags: staticDialedConn, node: newNode(uintID(1), nil)}},
{rw: &conn{flags: staticDialedConn, node: newNode(uintID(2), nil)}},
},
},
{
peers: []*Peer{
{rw: &conn{flags: staticDialedConn, node: newNode(uintID(1), nil)}},
{rw: &conn{flags: staticDialedConn, node: newNode(uintID(2), nil)}},
},
},
// The cache entry for node 3 has expired and is retried.
{
done: []task{
&waitExpireTask{Duration: 19 * time.Second},
},
peers: []*Peer{
{rw: &conn{flags: dynDialedConn, node: newNode(uintID(1), nil)}},
{rw: &conn{flags: dynDialedConn, node: newNode(uintID(2), nil)}},
{rw: &conn{flags: staticDialedConn, node: newNode(uintID(1), nil)}},
{rw: &conn{flags: staticDialedConn, node: newNode(uintID(2), nil)}},
},
new: []task{
&dialTask{flags: staticDialedConn, dest: newNode(uintID(3), nil)},
@ -594,9 +613,13 @@ func TestDialStateCache(t *testing.T) {
}
func TestDialResolve(t *testing.T) {
config := &Config{
Logger: testlog.Logger(t, log.LvlTrace),
Dialer: TCPDialer{&net.Dialer{Deadline: time.Now().Add(-5 * time.Minute)}},
}
resolved := newNode(uintID(1), net.IP{127, 0, 55, 234})
table := &resolveMock{answer: resolved}
state := newDialState(enode.ID{}, nil, nil, table, 0, nil)
state := newDialState(enode.ID{}, table, 0, config)
// Check that the task is generated with an incomplete ID.
dest := newNode(uintID(1), nil)
@ -607,8 +630,7 @@ func TestDialResolve(t *testing.T) {
}
// Now run the task, it should resolve the ID once.
config := Config{Dialer: TCPDialer{&net.Dialer{Deadline: time.Now().Add(-5 * time.Minute)}}}
srv := &Server{ntab: table, Config: config}
srv := &Server{ntab: table, log: config.Logger, Config: *config}
tasks[0].Do(srv)
if !reflect.DeepEqual(table.resolveCalls, []*enode.Node{dest}) {
t.Fatalf("wrong resolve calls, got %v", table.resolveCalls)

View file

@ -466,7 +466,7 @@ func (srv *Server) Start() (err error) {
}
dynPeers := srv.maxDialedConns()
dialer := newDialState(srv.localnode.ID(), srv.StaticNodes, srv.BootstrapNodes, srv.ntab, dynPeers, srv.NetRestrict)
dialer := newDialState(srv.localnode.ID(), srv.ntab, dynPeers, &srv.Config)
srv.loopWG.Add(1)
go srv.run(dialer)
return nil