From 527a88d156ca1005333d1f7c9916b8eaed3588c0 Mon Sep 17 00:00:00 2001 From: Daniel McNally Date: Thu, 15 Aug 2019 06:18:47 -0400 Subject: [PATCH] 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 | 23 ++++++++++++----------- test/p2p/networks.spec.ts | 5 +++-- test/p2p/sanity.spec.ts | 6 +++--- test/simulation/tests-integration.go | 6 ++++-- 4 files changed, 22 insertions(+), 18 deletions(-) diff --git a/lib/p2p/Peer.ts b/lib/p2p/Peer.ts index e9bfd2565..abfe7c801 100644 --- a/lib/p2p/Peer.ts +++ b/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 => { - 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) { diff --git a/test/p2p/networks.spec.ts b/test/p2p/networks.spec.ts index 983412daa..81f5dacbe 100644 --- a/test/p2p/networks.spec.ts +++ b/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); diff --git a/test/p2p/sanity.spec.ts b/test/p2p/sanity.spec.ts index 74b9e39e0..c01764bc8 100644 --- a/test/p2p/sanity.spec.ts +++ b/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 () => { diff --git a/test/simulation/tests-integration.go b/test/simulation/tests-integration.go index 438714715..356f0f242 100644 --- a/test/simulation/tests-integration.go +++ b/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)