feat(p2p): log peer's expectedpubkey

This modifies the log messages to print the expected pub key of a peer
(when we have one as is the case on outbound connections) along with
the peer's address before we have completed the handshake with that
peer. After the handshake, we log only the peer's pub key.

lib/p2p/Peer.ts

@@ -123,7 +123,9 @@ class Peer extends EventEmitter {
   }
 
   public get label(): string {
-    return this.nodePubKey || addressUtils.toString(this.address);
+    return this.nodePubKey ||
+      this.expectedNodePubKey ? `${this.expectedNodePubKey}@${addressUtils.toString(this.address)}` :
+      addressUtils.toString(this.address);
   }
 
   public get addresses(): Address[] | undefined {
@@ -219,8 +221,8 @@ class Peer extends EventEmitter {
     let status: string;
     if (this.connected) {
       status = this.nodePubKey ?
-        `Connected to peer ${this.nodePubKey}` :
-        `Connected pre-handshake to peer ${addressUtils.toString(this.address)}`;
+        `Connected to ${this.label}` :
+        `Connected pre-handshake to ${this.label}`;
     } else {
       status = 'Not connected';
     }
@@ -336,11 +338,11 @@ class Peer extends EventEmitter {
 
     let rejectionMsg;
     if (reason) {
-      rejectionMsg = `Peer (${this.label}) closed due to ${DisconnectionReason[reason]} ${reasonPayload || ''}`;
+      rejectionMsg = `Peer ${this.label} closed due to ${DisconnectionReason[reason]} ${reasonPayload || ''}`;
     } else if (this.recvDisconnectionReason) {
-      rejectionMsg = `Peer (${this.label}) disconnected from us due to ${DisconnectionReason[this.recvDisconnectionReason]}`;
+      rejectionMsg = `Peer ${this.label} disconnected from us due to ${DisconnectionReason[this.recvDisconnectionReason]}`;
     } else {
-      rejectionMsg = `Peer (${this.label}) was destroyed`;
+      rejectionMsg = `Peer ${this.label} was destroyed`;
     }
 
     for (const [packetType, entry] of this.responseMap) {
@@ -440,7 +442,7 @@ class Peer extends EventEmitter {
       try {
         this.socket.write(data);
       } catch (err) {
-        this.logger.error('failed sending data to peer', err);
+        this.logger.error(`failed sending data to ${this.label}`, err);
       }
     }
   }
@@ -512,7 +514,7 @@ class Peer extends EventEmitter {
         }
 
         this.logger.debug(
-          `Connection attempt #${retries + 1} to peer ${this.expectedNodePubKey}@${addressUtils.toString(this.address)} ` +
+          `Connection attempt #${retries + 1} to ${this.label}` +
           `failed: ${err.message}. retrying in ${retryDelay / 1000} sec...`,
         );
 
@@ -660,7 +662,7 @@ class Peer extends EventEmitter {
     this.socket!.once('close', async (hadError) => {
       // emitted once the socket is fully closed
       if (this.nodePubKey === undefined) {
-        this.logger.info(`Socket closed prior to handshake (${addressUtils.toString(this.address)})`);
+        this.logger.info(`Socket closed prior to handshake with ${this.label}`);
       } else if (hadError) {
         this.logger.warn(`Peer ${this.nodePubKey} socket closed due to error`);
       } else {
@@ -715,8 +717,7 @@ class Peer extends EventEmitter {
   }
 
   private handlePacket = async (packet: Packet): Promise<void> => {
-    const sender = this.nodePubKey !== undefined ? this.nodePubKey : addressUtils.toString(this.address);
-    this.logger.trace(`Received ${PacketType[packet.type]} packet from ${sender}${JSON.stringify(packet)}`);
+    this.logger.trace(`Received ${PacketType[packet.type]} packet from ${this.label}: ${JSON.stringify(packet)}`);
 
     if (await this.isPacketSolicited(packet)) {
       switch (packet.type) {

test/p2p/networks.spec.ts

@@ -19,9 +19,10 @@ describe('P2P Networks Tests', () => {
 
       const host = 'localhost';
       const port = destNode['pool']['listenPort']!;
-      const nodeTwoUri = toUri({ host, port, nodePubKey: destNode['pool'].nodePubKey });
+      const nodePubKey = destNode['pool'].nodePubKey;
+      const nodeTwoUri = toUri({ host, port, nodePubKey });
 
-      const rejectionMsg = `Peer (${host}:${port}) closed due to WireProtocolErr framer: incompatible msg origin network (expected: ${srcNodeNetwork}, found: ${destNodeNetwork})`;
+      const rejectionMsg = `Peer ${nodePubKey}@${host}:${port} closed due to WireProtocolErr framer: incompatible msg origin network (expected: ${srcNodeNetwork}, found: ${destNodeNetwork})`;
       await expect(srcNode.service.connect({ nodeUri: nodeTwoUri, retryConnecting: false })).to.be.rejectedWith(rejectionMsg);
 
       expect(await srcNode.service.listPeers().length).to.equal(0);

test/p2p/sanity.spec.ts

@@ -109,7 +109,7 @@ describe('P2P Sanity Tests', () => {
     const nodeUri = toUri({ host, port, nodePubKey: randomPubKey });
 
     const connectPromise = nodeOne.service.connect({ nodeUri, retryConnecting: false });
-    await expect(connectPromise).to.be.rejectedWith(`Peer (${host}:${port}) disconnected from us due to AuthFailureInvalidTarget`);
+    await expect(connectPromise).to.be.rejectedWith(`Peer ${randomPubKey}@${host}:${port} disconnected from us due to AuthFailureInvalidTarget`);
     const listPeersResult = await nodeOne.service.listPeers();
     expect(listPeersResult).to.be.empty;
   });
@@ -121,7 +121,7 @@ describe('P2P Sanity Tests', () => {
     const nodeUri = toUri({ host, port, nodePubKey: invalidPubKey });
 
     const connectPromise = nodeOne.service.connect({ nodeUri, retryConnecting: false });
-    await expect(connectPromise).to.be.rejectedWith(`Peer (${host}:${port}) disconnected from us due to AuthFailureInvalidTarget`);
+    await expect(connectPromise).to.be.rejectedWith(`Peer ${invalidPubKey}@${host}:${port} disconnected from us due to AuthFailureInvalidTarget`);
     const listPeersResult = await nodeOne.service.listPeers();
     expect(listPeersResult).to.be.empty;
   });
@@ -159,7 +159,7 @@ describe('P2P Sanity Tests', () => {
   it('should fail when connecting to a node that has banned us', async () => {
     await nodeTwo.service.ban({ nodePubKey: nodeOnePubKey });
     await expect(nodeOne.service.connect({ nodeUri: nodeTwoUri, retryConnecting: false }))
-      .to.be.rejectedWith(`Peer (localhost:${nodeTwoPort}) disconnected from us due to Banned`);
+      .to.be.rejectedWith(`Peer ${nodeTwoPubKey}@localhost:${nodeTwoPort} disconnected from us due to Banned`);
   });
 
   after(async () => {

test/simulation/tests-integration.go

@@ -102,7 +102,8 @@ func testP2PIncorrectPubKey(net *xudtest.NetworkHarness, ht *harnessTest) {
 	_, err := net.Alice.Client.Connect(ht.ctx, reqConn)
 	ht.assert.Error(err)
 	ht.assert.Contains(err.Error(), fmt.Sprintf(
-		"Peer (%v) disconnected from us due to AuthFailureInvalidTarget", net.Bob.Cfg.P2PAddr()))
+		"Peer %v disconnected from us due to AuthFailureInvalidTarget",
+		incorrectPubKey + "@" + net.Bob.Cfg.P2PAddr()))
 }
 
 // testP2PBanUnban implements:
@@ -124,7 +125,8 @@ func testP2PBanUnban(net *xudtest.NetworkHarness, ht *harnessTest) {
 	_, err = net.Bob.Client.Connect(ht.ctx, reqConn)
 	ht.assert.Error(err)
 	ht.assert.Contains(err.Error(), fmt.Sprintf(
-		" Peer (%v) disconnected from us due to Banned", net.Alice.Cfg.P2PAddr()))
+		" Peer %v disconnected from us due to Banned",
+		net.Alice.PubKey() + "@" + net.Alice.Cfg.P2PAddr()))
 
 	// After Alice unban Bob, connection attempts from both directions should succeed.
 	ht.act.unban(net.Alice, net.Bob)