diff --git a/p2p/dial.go b/p2p/dial.go index b8855136f3..8dee5063f1 100644 --- a/p2p/dial.go +++ b/p2p/dial.go @@ -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 } diff --git a/p2p/dial_test.go b/p2p/dial_test.go index 48d356144b..de8fc4a6e3 100644 --- a/p2p/dial_test.go +++ b/p2p/dial_test.go @@ -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{ - newNode(uintID(1), nil), - newNode(uintID(2), nil), - newNode(uintID(3), nil), + 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{ - newNode(uintID(1), nil), - newNode(uintID(2), nil), - newNode(uintID(3), nil), - newNode(uintID(4), nil), - newNode(uintID(5), nil), + 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{ - newNode(uintID(1), nil), - newNode(uintID(2), nil), - newNode(uintID(3), nil), + 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) diff --git a/p2p/server.go b/p2p/server.go index 06dc95f222..94c5231868 100644 --- a/p2p/server.go +++ b/p2p/server.go @@ -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