From b14dfea553e2d67660b1c5d90add72fbf0c47940 Mon Sep 17 00:00:00 2001 From: Kim De Mey Date: Thu, 17 Mar 2022 13:19:36 +0100 Subject: [PATCH] Improve portal wire logging by adding protocolId (#997) --- fluffy/network/wire/portal_protocol.nim | 40 +++++++++++++++++-------- 1 file changed, 27 insertions(+), 13 deletions(-) diff --git a/fluffy/network/wire/portal_protocol.nim b/fluffy/network/wire/portal_protocol.nim index 6c20377de..0500ce1cd 100644 --- a/fluffy/network/wire/portal_protocol.nim +++ b/fluffy/network/wire/portal_protocol.nim @@ -12,7 +12,7 @@ import std/[sequtils, sets, algorithm], - stew/results, chronicles, chronos, nimcrypto/hash, bearssl, + stew/[results, byteutils], chronicles, chronos, nimcrypto/hash, bearssl, ssz_serialization, eth/rlp, eth/p2p/discoveryv5/[protocol, node, enr, routing_table, random2, nodes_verification, lru], @@ -70,6 +70,9 @@ type of Nodes: nodes*: seq[Node] +func `$`(id: PortalProtocolId): string = + id.toHex() + proc addNode*(p: PortalProtocol, node: Node): NodeStatus = p.routingTable.addNode(node) @@ -202,6 +205,9 @@ proc messageHandler(protocol: TalkProtocol, request: seq[byte], srcId: NodeId, srcUdpAddress: Address): seq[byte] = doAssert(protocol of PortalProtocol) + logScope: + protocolId = p.protocolId + let p = PortalProtocol(protocol) let decoded = decodeMessage(request) @@ -281,11 +287,16 @@ proc new*(T: type PortalProtocol, # validates the proper response, and updates the Portal Network routing table. proc reqResponse[Request: SomeMessage, Response: SomeMessage]( p: PortalProtocol, - toNode: Node, + dst: Node, request: Request ): Future[PortalResult[Response]] {.async.} = + logScope: + protocolId = p.protocolId + + trace "Send message request", dstId = dst.id, kind = messageKind(Request) + let talkresp = - await talkreq(p.baseProtocol, toNode, @(p.protocolId), encodeMessage(request)) + await talkreq(p.baseProtocol, dst, @(p.protocolId), encodeMessage(request)) # Note: Failure of `decodeMessage` might also simply mean that the peer is # not supporting the specific talk protocol, as according to specification @@ -299,13 +310,13 @@ proc reqResponse[Request: SomeMessage, Response: SomeMessage]( ) if messageResponse.isOk(): - trace "Received message response", srcId = toNode.id, - srcAddress = toNode.address, kind = messageKind(Response) - p.routingTable.setJustSeen(toNode) + trace "Received message response", srcId = dst.id, + srcAddress = dst.address, kind = messageKind(Response) + p.routingTable.setJustSeen(dst) else: debug "Error receiving message response", error = messageResponse.error, - srcId = toNode.id, srcAddress = toNode.address - p.routingTable.replaceNode(toNode) + srcId = dst.id, srcAddress = dst.address + p.routingTable.replaceNode(dst) return messageResponse @@ -315,14 +326,12 @@ proc pingImpl*(p: PortalProtocol, dst: Node): let ping = PingMessage(enrSeq: p.baseProtocol.localNode.record.seqNum, customPayload: ByteList(SSZ.encode(customPayload))) - trace "Send message request", dstId = dst.id, kind = MessageKind.ping return await reqResponse[PingMessage, PongMessage](p, dst, ping) proc findNodes*(p: PortalProtocol, dst: Node, distances: List[uint16, 256]): Future[PortalResult[NodesMessage]] {.async.} = let fn = FindNodesMessage(distances: distances) - trace "Send message request", dstId = dst.id, kind = MessageKind.findnodes # TODO Add nodes validation return await reqResponse[FindNodesMessage, NodesMessage](p, dst, fn) @@ -330,15 +339,12 @@ proc findContentImpl*(p: PortalProtocol, dst: Node, contentKey: ByteList): Future[PortalResult[ContentMessage]] {.async.} = let fc = FindContentMessage(contentKey: contentKey) - trace "Send message request", dstId = dst.id, kind = MessageKind.findcontent return await reqResponse[FindContentMessage, ContentMessage](p, dst, fc) proc offerImpl*(p: PortalProtocol, dst: Node, contentKeys: ContentKeysList): Future[PortalResult[AcceptMessage]] {.async.} = let offer = OfferMessage(contentKeys: contentKeys) - trace "Send message request", dstId = dst.id, kind = MessageKind.offer - return await reqResponse[OfferMessage, AcceptMessage](p, dst, offer) proc recordsFromBytes*(rawRecords: List[ByteList, 32]): PortalResult[seq[Record]] = @@ -744,6 +750,8 @@ proc seedTable*(p: PortalProtocol) = # bootstrap the portal networks, however it would require a flag in the ENR to # be added and there might be none in the routing table due to low amount of # Portal nodes versus other nodes. + logScope: + protocolId = p.protocolId for record in p.bootstrapRecords: if p.addNode(record): @@ -756,6 +764,9 @@ proc seedTable*(p: PortalProtocol) = proc populateTable(p: PortalProtocol) {.async.} = ## Do a set of initial lookups to quickly populate the table. # start with a self target query (neighbour nodes) + logScope: + protocolId = p.protocolId + let selfQuery = await p.query(p.baseProtocol.localNode.id) trace "Discovered nodes in self target query", nodes = selfQuery.len @@ -795,6 +806,9 @@ proc refreshLoop(p: PortalProtocol) {.async.} = ## Loop that refreshes the routing table by starting a random query in case ## no queries were done since `refreshInterval` or more. ## It also refreshes the majority address voted for via pong responses. + logScope: + protocolId = p.protocolId + try: while true: # TODO: It would be nicer and more secure if this was event based and/or