p2p/discover, p2p/enode: rework endpoint proof handling, packet logging (#18963)

This change resolves multiple issues around handling of endpoint proofs.
The proof is now done separately for each IP and completing the proof
requires a matching ping hash.

Also remove waitping because it's equivalent to sleep. waitping was
slightly more efficient, but that may cause issues with findnode if
packets are reordered and the remote end sees findnode before pong.

Logging of received packets was hitherto done after handling the packet,
which meant that sent replies were logged before the packet that
generated them. This change splits up packet handling into 'preverify'
and 'handle'. The error from 'preverify' is logged, but 'handle' happens
after the message is logged. This fixes the order. Packet logs now
contain the node ID.

1 files changed, 154 insertions, 62 deletions

diff --git a/p2p/enode/nodedb_test.go b/p2p/enode/nodedb_test.go
index 96794827c..341b61a28 100644
--- a/p2p/enode/nodedb_test.go
+++ b/p2p/enode/nodedb_test.go
@@ -28,42 +28,54 @@ import (
 	"time"
 )
 
-var nodeDBKeyTests = []struct {
-	id    ID
-	field string
-	key   []byte
-}{
-	{
-		id:    ID{},
-		field: "version",
-		key:   []byte{0x76, 0x65, 0x72, 0x73, 0x69, 0x6f, 0x6e}, // field
-	},
-	{
-		id:    HexID("51232b8d7821617d2b29b54b81cdefb9b3e9c37d7fd5f63270bcc9e1a6f6a439"),
-		field: ":discover",
-		key: []byte{
-			0x6e, 0x3a, // prefix
-			0x51, 0x23, 0x2b, 0x8d, 0x78, 0x21, 0x61, 0x7d, // node id
-			0x2b, 0x29, 0xb5, 0x4b, 0x81, 0xcd, 0xef, 0xb9, //
-			0xb3, 0xe9, 0xc3, 0x7d, 0x7f, 0xd5, 0xf6, 0x32, //
-			0x70, 0xbc, 0xc9, 0xe1, 0xa6, 0xf6, 0xa4, 0x39, //
-			0x3a, 0x64, 0x69, 0x73, 0x63, 0x6f, 0x76, 0x65, 0x72, // field
-		},
-	},
+var keytestID = HexID("51232b8d7821617d2b29b54b81cdefb9b3e9c37d7fd5f63270bcc9e1a6f6a439")
+
+func TestDBNodeKey(t *testing.T) {
+	enc := nodeKey(keytestID)
+	want := []byte{
+		'n', ':',
+		0x51, 0x23, 0x2b, 0x8d, 0x78, 0x21, 0x61, 0x7d, // node id
+		0x2b, 0x29, 0xb5, 0x4b, 0x81, 0xcd, 0xef, 0xb9, //
+		0xb3, 0xe9, 0xc3, 0x7d, 0x7f, 0xd5, 0xf6, 0x32, //
+		0x70, 0xbc, 0xc9, 0xe1, 0xa6, 0xf6, 0xa4, 0x39, //
+		':', 'v', '4',
+	}
+	if !bytes.Equal(enc, want) {
+		t.Errorf("wrong encoded key:\ngot  %q\nwant %q", enc, want)
+	}
+	id, _ := splitNodeKey(enc)
+	if id != keytestID {
+		t.Errorf("wrong ID from splitNodeKey")
+	}
 }
 
-func TestDBKeys(t *testing.T) {
-	for i, tt := range nodeDBKeyTests {
-		if key := makeKey(tt.id, tt.field); !bytes.Equal(key, tt.key) {
-			t.Errorf("make test %d: key mismatch: have 0x%x, want 0x%x", i, key, tt.key)
-		}
-		id, field := splitKey(tt.key)
-		if !bytes.Equal(id[:], tt.id[:]) {
-			t.Errorf("split test %d: id mismatch: have 0x%x, want 0x%x", i, id, tt.id)
-		}
-		if field != tt.field {
-			t.Errorf("split test %d: field mismatch: have 0x%x, want 0x%x", i, field, tt.field)
-		}
+func TestDBNodeItemKey(t *testing.T) {
+	wantIP := net.IP{127, 0, 0, 3}
+	wantField := "foobar"
+	enc := nodeItemKey(keytestID, wantIP, wantField)
+	want := []byte{
+		'n', ':',
+		0x51, 0x23, 0x2b, 0x8d, 0x78, 0x21, 0x61, 0x7d, // node id
+		0x2b, 0x29, 0xb5, 0x4b, 0x81, 0xcd, 0xef, 0xb9, //
+		0xb3, 0xe9, 0xc3, 0x7d, 0x7f, 0xd5, 0xf6, 0x32, //
+		0x70, 0xbc, 0xc9, 0xe1, 0xa6, 0xf6, 0xa4, 0x39, //
+		':', 'v', '4', ':',
+		0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, // IP
+		0x00, 0x00, 0xff, 0xff, 0x7f, 0x00, 0x00, 0x03, //
+		':', 'f', 'o', 'o', 'b', 'a', 'r',
+	}
+	if !bytes.Equal(enc, want) {
+		t.Errorf("wrong encoded key:\ngot  %q\nwant %q", enc, want)
+	}
+	id, ip, field := splitNodeItemKey(enc)
+	if id != keytestID {
+		t.Errorf("splitNodeItemKey returned wrong ID: %v", id)
+	}
+	if !bytes.Equal(ip, wantIP) {
+		t.Errorf("splitNodeItemKey returned wrong IP: %v", ip)
+	}
+	if field != wantField {
+		t.Errorf("splitNodeItemKey returned wrong field: %q", field)
 	}
 }
 
@@ -113,33 +125,33 @@ func TestDBFetchStore(t *testing.T) {
 	defer db.Close()
 
 	// Check fetch/store operations on a node ping object
-	if stored := db.LastPingReceived(node.ID()); stored.Unix() != 0 {
+	if stored := db.LastPingReceived(node.ID(), node.IP()); stored.Unix() != 0 {
 		t.Errorf("ping: non-existing object: %v", stored)
 	}
-	if err := db.UpdateLastPingReceived(node.ID(), inst); err != nil {
+	if err := db.UpdateLastPingReceived(node.ID(), node.IP(), inst); err != nil {
 		t.Errorf("ping: failed to update: %v", err)
 	}
-	if stored := db.LastPingReceived(node.ID()); stored.Unix() != inst.Unix() {
+	if stored := db.LastPingReceived(node.ID(), node.IP()); stored.Unix() != inst.Unix() {
 		t.Errorf("ping: value mismatch: have %v, want %v", stored, inst)
 	}
 	// Check fetch/store operations on a node pong object
-	if stored := db.LastPongReceived(node.ID()); stored.Unix() != 0 {
+	if stored := db.LastPongReceived(node.ID(), node.IP()); stored.Unix() != 0 {
 		t.Errorf("pong: non-existing object: %v", stored)
 	}
-	if err := db.UpdateLastPongReceived(node.ID(), inst); err != nil {
+	if err := db.UpdateLastPongReceived(node.ID(), node.IP(), inst); err != nil {
 		t.Errorf("pong: failed to update: %v", err)
 	}
-	if stored := db.LastPongReceived(node.ID()); stored.Unix() != inst.Unix() {
+	if stored := db.LastPongReceived(node.ID(), node.IP()); stored.Unix() != inst.Unix() {
 		t.Errorf("pong: value mismatch: have %v, want %v", stored, inst)
 	}
 	// Check fetch/store operations on a node findnode-failure object
-	if stored := db.FindFails(node.ID()); stored != 0 {
+	if stored := db.FindFails(node.ID(), node.IP()); stored != 0 {
 		t.Errorf("find-node fails: non-existing object: %v", stored)
 	}
-	if err := db.UpdateFindFails(node.ID(), num); err != nil {
+	if err := db.UpdateFindFails(node.ID(), node.IP(), num); err != nil {
 		t.Errorf("find-node fails: failed to update: %v", err)
 	}
-	if stored := db.FindFails(node.ID()); stored != num {
+	if stored := db.FindFails(node.ID(), node.IP()); stored != num {
 		t.Errorf("find-node fails: value mismatch: have %v, want %v", stored, num)
 	}
 	// Check fetch/store operations on an actual node object
@@ -256,7 +268,7 @@ func testSeedQuery() error {
 		if err := db.UpdateNode(seed.node); err != nil {
 			return fmt.Errorf("node %d: failed to insert: %v", i, err)
 		}
-		if err := db.UpdateLastPongReceived(seed.node.ID(), seed.pong); err != nil {
+		if err := db.UpdateLastPongReceived(seed.node.ID(), seed.node.IP(), seed.pong); err != nil {
 			return fmt.Errorf("node %d: failed to insert bondTime: %v", i, err)
 		}
 	}
@@ -321,10 +333,12 @@ func TestDBPersistency(t *testing.T) {
 }
 
 var nodeDBExpirationNodes = []struct {
-	node *Node
-	pong time.Time
-	exp  bool
+	node      *Node
+	pong      time.Time
+	storeNode bool
+	exp       bool
 }{
+	// Node has new enough pong time and isn't expired:
 	{
 		node: NewV4(
 			hexPubkey("8d110e2ed4b446d9b5fb50f117e5f37fb7597af455e1dab0e6f045a6eeaa786a6781141659020d38bdc5e698ed3d4d2bafa8b5061810dfa63e8ac038db2e9b67"),
@@ -332,17 +346,79 @@ var nodeDBExpirationNodes = []struct {
 			30303,
 			30303,
 		),
-		pong: time.Now().Add(-dbNodeExpiration + time.Minute),
-		exp:  false,
-	}, {
+		storeNode: true,
+		pong:      time.Now().Add(-dbNodeExpiration + time.Minute),
+		exp:       false,
+	},
+	// Node with pong time before expiration is removed:
+	{
 		node: NewV4(
 			hexPubkey("913a205579c32425b220dfba999d215066e5bdbf900226b11da1907eae5e93eb40616d47412cf819664e9eacbdfcca6b0c6e07e09847a38472d4be46ab0c3672"),
 			net.IP{127, 0, 0, 2},
 			30303,
 			30303,
 		),
-		pong: time.Now().Add(-dbNodeExpiration - time.Minute),
-		exp:  true,
+		storeNode: true,
+		pong:      time.Now().Add(-dbNodeExpiration - time.Minute),
+		exp:       true,
+	},
+	// Just pong time, no node stored:
+	{
+		node: NewV4(
+			hexPubkey("b56670e0b6bad2c5dab9f9fe6f061a16cf78d68b6ae2cfda3144262d08d97ce5f46fd8799b6d1f709b1abe718f2863e224488bd7518e5e3b43809ac9bd1138ca"),
+			net.IP{127, 0, 0, 3},
+			30303,
+			30303,
+		),
+		storeNode: false,
+		pong:      time.Now().Add(-dbNodeExpiration - time.Minute),
+		exp:       true,
+	},
+	// Node with multiple pong times, all older than expiration.
+	{
+		node: NewV4(
+			hexPubkey("29f619cebfd32c9eab34aec797ed5e3fe15b9b45be95b4df3f5fe6a9ae892f433eb08d7698b2ef3621568b0fb70d57b515ab30d4e72583b798298e0f0a66b9d1"),
+			net.IP{127, 0, 0, 4},
+			30303,
+			30303,
+		),
+		storeNode: true,
+		pong:      time.Now().Add(-dbNodeExpiration - time.Minute),
+		exp:       true,
+	},
+	{
+		node: NewV4(
+			hexPubkey("29f619cebfd32c9eab34aec797ed5e3fe15b9b45be95b4df3f5fe6a9ae892f433eb08d7698b2ef3621568b0fb70d57b515ab30d4e72583b798298e0f0a66b9d1"),
+			net.IP{127, 0, 0, 5},
+			30303,
+			30303,
+		),
+		storeNode: false,
+		pong:      time.Now().Add(-dbNodeExpiration - 2*time.Minute),
+		exp:       true,
+	},
+	// Node with multiple pong times, one newer, one older than expiration.
+	{
+		node: NewV4(
+			hexPubkey("3b73a9e5f4af6c4701c57c73cc8cfa0f4802840b24c11eba92aac3aef65644a3728b4b2aec8199f6d72bd66be2c65861c773129039bd47daa091ca90a6d4c857"),
+			net.IP{127, 0, 0, 6},
+			30303,
+			30303,
+		),
+		storeNode: true,
+		pong:      time.Now().Add(-dbNodeExpiration + time.Minute),
+		exp:       false,
+	},
+	{
+		node: NewV4(
+			hexPubkey("3b73a9e5f4af6c4701c57c73cc8cfa0f4802840b24c11eba92aac3aef65644a3728b4b2aec8199f6d72bd66be2c65861c773129039bd47daa091ca90a6d4c857"),
+			net.IP{127, 0, 0, 7},
+			30303,
+			30303,
+		),
+		storeNode: false,
+		pong:      time.Now().Add(-dbNodeExpiration - time.Minute),
+		exp:       true,
 	},
 }
 
@@ -350,23 +426,39 @@ func TestDBExpiration(t *testing.T) {
 	db, _ := OpenDB("")
 	defer db.Close()
 
-	// Add all the test nodes and set their last pong time
+	// Add all the test nodes and set their last pong time.
 	for i, seed := range nodeDBExpirationNodes {
-		if err := db.UpdateNode(seed.node); err != nil {
-			t.Fatalf("node %d: failed to insert: %v", i, err)
+		if seed.storeNode {
+			if err := db.UpdateNode(seed.node); err != nil {
+				t.Fatalf("node %d: failed to insert: %v", i, err)
+			}
 		}
-		if err := db.UpdateLastPongReceived(seed.node.ID(), seed.pong); err != nil {
+		if err := db.UpdateLastPongReceived(seed.node.ID(), seed.node.IP(), seed.pong); err != nil {
 			t.Fatalf("node %d: failed to update bondTime: %v", i, err)
 		}
 	}
-	// Expire some of them, and check the rest
-	if err := db.expireNodes(); err != nil {
-		t.Fatalf("failed to expire nodes: %v", err)
-	}
+
+	db.expireNodes()
+
+	// Check that expired entries have been removed.
+	unixZeroTime := time.Unix(0, 0)
 	for i, seed := range nodeDBExpirationNodes {
 		node := db.Node(seed.node.ID())
-		if (node == nil && !seed.exp) || (node != nil && seed.exp) {
-			t.Errorf("node %d: expiration mismatch: have %v, want %v", i, node, seed.exp)
+		pong := db.LastPongReceived(seed.node.ID(), seed.node.IP())
+		if seed.exp {
+			if seed.storeNode && node != nil {
+				t.Errorf("node %d (%s) shouldn't be present after expiration", i, seed.node.ID().TerminalString())
+			}
+			if !pong.Equal(unixZeroTime) {
+				t.Errorf("pong time %d (%s %v) shouldn't be present after expiration", i, seed.node.ID().TerminalString(), seed.node.IP())
+			}
+		} else {
+			if seed.storeNode && node == nil {
+				t.Errorf("node %d (%s) should be present after expiration", i, seed.node.ID().TerminalString())
+			}
+			if !pong.Equal(seed.pong.Truncate(1 * time.Second)) {
+				t.Errorf("pong time %d (%s) should be %v after expiration, but is %v", i, seed.node.ID().TerminalString(), seed.pong, pong)
+			}
 		}
 	}
 }