From a87648fded4052fca4d51da4e98e374adadf3a5d Mon Sep 17 00:00:00 2001 From: Reynold Morel Date: Tue, 24 Oct 2023 10:34:11 -0400 Subject: [PATCH 01/17] Add extra logs to peer discovery --- .../co/rsk/net/discovery/PeerExplorer.java | 27 ++++++++++++++++--- .../discovery/table/NodeDistanceTable.java | 6 +++++ 2 files changed, 30 insertions(+), 3 deletions(-) diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java index cc2d86bda19..737c8bef154 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java @@ -170,6 +170,7 @@ synchronized void handleMessage(DiscoveryEvent event) { //have a networkId in the message yet, then just let them through, for now. if (event.getMessage().getNetworkId().isPresent() && event.getMessage().getNetworkId().getAsInt() != this.networkId) { + logger.debug("Message ignored due to different network id {}", event.getMessage().getNetworkId().getAsInt()); return; } if (type == DiscoveryMessageType.PING) { @@ -181,7 +182,7 @@ synchronized void handleMessage(DiscoveryEvent event) { } if (type == DiscoveryMessageType.FIND_NODE) { - this.handleFindNode((FindNodePeerMessage) event.getMessage()); + this.handleFindNode(event.getAddress(), (FindNodePeerMessage) event.getMessage()); } if (type == DiscoveryMessageType.NEIGHBORS) { @@ -190,6 +191,7 @@ synchronized void handleMessage(DiscoveryEvent event) { } private void handlePingMessage(InetSocketAddress address, PingPeerMessage message) { + logger.debug("Handling ping message received from ip:[{}] port:[{}]", address.getHostName(), address.getPort()); this.sendPong(address, message); Node connectedNode = this.establishedConnections.get(message.getNodeId()); @@ -202,6 +204,7 @@ private void handlePingMessage(InetSocketAddress address, PingPeerMessage messag } private void handlePong(InetSocketAddress pongAddress, PongPeerMessage message) { + logger.debug("Handling pong message received from ip:[{}] port:[{}]", pongAddress.getHostName(), pongAddress.getPort()); PeerDiscoveryRequest request = this.pendingPingRequests.get(message.getMessageId()); if (request != null && request.validateMessageResponse(pongAddress, message)) { @@ -213,7 +216,8 @@ private void handlePong(InetSocketAddress pongAddress, PongPeerMessage message) } } - private void handleFindNode(FindNodePeerMessage message) { + private void handleFindNode(InetSocketAddress findNodeAddress, FindNodePeerMessage message) { + logger.debug("Handling find node message received from ip:[{}] port:[{}]", findNodeAddress.getHostName(), findNodeAddress.getPort()); NodeID nodeId = message.getNodeId(); Node connectedNode = this.establishedConnections.get(nodeId); @@ -226,6 +230,7 @@ private void handleFindNode(FindNodePeerMessage message) { } private void handleNeighborsMessage(InetSocketAddress neighborsResponseAddress, NeighborsPeerMessage message) { + logger.debug("Handling neighbors message received from ip:[{}] port:[{}]", neighborsResponseAddress.getHostName(), neighborsResponseAddress.getPort()); Node connectedNode = this.establishedConnections.get(message.getNodeId()); if (connectedNode != null) { @@ -271,10 +276,13 @@ synchronized PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt pendingPingRequests.put(nodeMessage.getMessageId(), request); + logger.debug("Ping message with id {} sent to ip:[{}] port:[{}] on attempt #{}", nodeMessage.getMessageId(), nodeAddress.getAddress().getHostAddress(), nodeAddress.getPort(), attempt); + return nodeMessage; } private void updateEntry(Node connectedNode) { + logger.trace("Updating node with id {}", connectedNode.getHexId()); try { updateEntryLock.lock(); this.distanceTable.updateEntry(connectedNode); @@ -297,6 +305,7 @@ private PongPeerMessage sendPong(InetSocketAddress nodeAddress, PingPeerMessage InetSocketAddress localAddress = this.localNode.getAddress(); PongPeerMessage pongPeerMessage = PongPeerMessage.create(localAddress.getHostName(), localAddress.getPort(), message.getMessageId(), this.key, this.networkId); udpChannel.write(new DiscoveryEvent(pongPeerMessage, nodeAddress)); + logger.debug("Pong message with id {} sent to ip:[{}] port:[{}]", pongPeerMessage.getMessageId(), nodeAddress.getAddress().getHostAddress(), nodeAddress.getPort()); return pongPeerMessage; } @@ -312,6 +321,8 @@ FindNodePeerMessage sendFindNode(Node node) { .expirationPeriod(requestTimeout).build(); pendingFindNodeRequests.put(findNodePeerMessage.getMessageId(), request); + logger.debug("Find node message with id {} sent to ip:[{}] port:[{}]", findNodePeerMessage.getMessageId(), nodeAddress.getAddress().getHostAddress(), nodeAddress.getPort()); + return findNodePeerMessage; } @@ -319,7 +330,8 @@ private NeighborsPeerMessage sendNeighbors(InetSocketAddress nodeAddress, List nodesToSend = getRandomizeLimitedList(nodes, MAX_NODES_PER_MSG, 5); NeighborsPeerMessage sendNodesMessage = NeighborsPeerMessage.create(nodesToSend, id, this.key, networkId); udpChannel.write(new DiscoveryEvent(sendNodesMessage, nodeAddress)); - logger.debug(" [{}] Neighbors Sent to ip:[{}] port:[{}]", nodesToSend.size(), nodeAddress.getAddress().getHostAddress(), nodeAddress.getPort()); + + logger.debug(" [{}] Neighbors sent on message with id {} to ip:[{}] port:[{}]", nodesToSend.size(), sendNodesMessage.getMessageId(), nodeAddress.getAddress().getHostAddress(), nodeAddress.getPort()); return sendNodesMessage; } @@ -335,6 +347,7 @@ private void purgeRequests() { } synchronized void clean() { + logger.trace("Cleaning expired requests"); if (state != ExecState.RUNNING) { logger.warn("Cannot clean as current state is {}", state); return; @@ -344,6 +357,7 @@ synchronized void clean() { } synchronized void update() { + logger.trace("Updating nodes list"); if (state != ExecState.RUNNING) { logger.warn("Cannot update as current state is {}", state); return; @@ -356,15 +370,18 @@ synchronized void update() { private void checkPeersPulse(List closestNodes) { List nodesToCheck = this.getRandomizeLimitedList(closestNodes, MAX_NODES_TO_CHECK, 10); + logger.trace("Checking peers pulse for {} nodes", nodesToCheck.size()); nodesToCheck.forEach(node -> sendPing(node.getAddress(), 1, node)); } private void askForMoreNodes(List closestNodes) { List nodesToAsk = getRandomizeLimitedList(closestNodes, MAX_NODES_TO_ASK, 5); + logger.trace("Asking for {} nodes", nodesToAsk.size()); nodesToAsk.forEach(this::sendFindNode); } private List removeExpiredRequests(Map pendingRequests) { + logger.trace("Removing expired requests"); List requests = pendingRequests.values().stream() .filter(PeerDiscoveryRequest::hasExpired).collect(Collectors.toList()); requests.forEach(r -> pendingRequests.remove(r.getMessageId())); @@ -377,6 +394,7 @@ private void removeExpiredChallenges(List peerDiscoveryReq } private void resendExpiredPing(List peerDiscoveryRequests) { + logger.trace("Resending expired pings"); peerDiscoveryRequests.stream().filter(r -> r.getAttemptNumber() < RETRIES_COUNT) .forEach(r -> sendPing(r.getAddress(), r.getAttemptNumber() + 1, r.getRelatedNode())); } @@ -392,6 +410,7 @@ private void removeConnections(List expiredRequests) { } private void removeConnection(Node node) { + logger.debug("Removing node with id {}", node.getId()); this.establishedConnections.remove(node.getId()); this.distanceTable.removeNode(node); this.knownHosts.remove(node.getAddressAsString()); @@ -408,6 +427,7 @@ private void addConnection(PongPeerMessage message, String ip, int port) { disconnectPeerIfDuplicatedByNodeId(senderNode, ip, port); } + logger.debug("Adding node with id {}", senderNode.getId()); OperationResult result = this.distanceTable.addNode(senderNode); if (result.isSuccess()) { this.knownHosts.put(senderNode.getAddressAsString(), senderNode.getId()); @@ -415,6 +435,7 @@ private void addConnection(PongPeerMessage message, String ip, int port) { logger.debug("New Peer found or id changed: ip[{}] port[{}] id [{}]", ip, port, senderNode.getId()); } else { this.challengeManager.startChallenge(result.getAffectedEntry().getNode(), senderNode, this); + logger.debug("Challenge started for node with id {}", result.getAffectedEntry().getNode().getId()); } } diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java b/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java index 3e9397a36aa..ef97ad02ca3 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java @@ -19,7 +19,11 @@ package co.rsk.net.discovery.table; import co.rsk.net.NodeID; +import co.rsk.net.discovery.PeerExplorer; import org.ethereum.net.rlpx.Node; +import org.ethereum.util.ByteUtil; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import java.util.*; import java.util.concurrent.ConcurrentHashMap; @@ -29,6 +33,7 @@ * Created by mario on 21/02/17. */ public class NodeDistanceTable { + private static final Logger logger = LoggerFactory.getLogger(NodeDistanceTable.class); private final Map buckets = new ConcurrentHashMap<>(); private final Node localNode; private final DistanceCalculator distanceCalculator; @@ -51,6 +56,7 @@ public synchronized OperationResult removeNode(Node node) { } public synchronized List getClosestNodes(NodeID nodeId) { + logger.trace("Getting closest nodes to id {}", ByteUtil.toHexString(nodeId.getID())); return getAllNodes().stream() .sorted(new NodeDistanceComparator(nodeId, this.distanceCalculator)) .collect(Collectors.toList()); From 607aa088a12c1d434db8ddb391ac8271b1abb05e Mon Sep 17 00:00:00 2001 From: Reynold Morel Date: Tue, 24 Oct 2023 10:37:26 -0400 Subject: [PATCH 02/17] Remove unused import --- .../main/java/co/rsk/net/discovery/table/NodeDistanceTable.java | 1 - 1 file changed, 1 deletion(-) diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java b/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java index ef97ad02ca3..fb1dcc2b277 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java @@ -19,7 +19,6 @@ package co.rsk.net.discovery.table; import co.rsk.net.NodeID; -import co.rsk.net.discovery.PeerExplorer; import org.ethereum.net.rlpx.Node; import org.ethereum.util.ByteUtil; import org.slf4j.Logger; From da8bf3066ffcc97502ebc4310f0ef175b913e0fe Mon Sep 17 00:00:00 2001 From: Reynold Morel Date: Tue, 24 Oct 2023 15:28:58 -0400 Subject: [PATCH 03/17] Add method variables to logs --- .../co/rsk/net/discovery/DiscoveryEvent.java | 9 ++ .../net/discovery/NodeChallengeManager.java | 8 ++ .../net/discovery/PeerDiscoveryRequest.java | 12 ++ .../co/rsk/net/discovery/PeerExplorer.java | 119 ++++++++++++++---- .../discovery/table/NodeDistanceTable.java | 5 +- 5 files changed, 128 insertions(+), 25 deletions(-) diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/DiscoveryEvent.java b/rskj-core/src/main/java/co/rsk/net/discovery/DiscoveryEvent.java index d306a09b9c2..7ab0f394676 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/DiscoveryEvent.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/DiscoveryEvent.java @@ -19,6 +19,7 @@ package co.rsk.net.discovery; import co.rsk.net.discovery.message.PeerDiscoveryMessage; +import org.apache.commons.lang3.builder.ToStringBuilder; import java.net.InetSocketAddress; @@ -38,4 +39,12 @@ public PeerDiscoveryMessage getMessage() { public InetSocketAddress getAddress() { return address; } + + @Override + public String toString() { + return new ToStringBuilder(this) + .append("message", this.message.toString()) + .append("address", this.address.toString()) + .toString(); + } } diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java b/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java index ef2878b5b14..ed26ba25698 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java @@ -21,6 +21,8 @@ import co.rsk.net.discovery.message.PingPeerMessage; import com.google.common.annotations.VisibleForTesting; import org.ethereum.net.rlpx.Node; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import java.util.Map; import java.util.concurrent.ConcurrentHashMap; @@ -29,9 +31,15 @@ * Created by mario on 22/02/17. */ public class NodeChallengeManager { + private static final Logger logger = LoggerFactory.getLogger(NodeChallengeManager.class); + private Map activeChallenges = new ConcurrentHashMap<>(); public NodeChallenge startChallenge(Node challengedNode, Node challenger, PeerExplorer explorer) { + logger.debug("co.rsk.net.discovery.NodeChallengeManager.startChallenge - Starting challenge for node:\n" + + "challengedNode: {}\n" + + "challenger: {}", challengedNode.toString(), challenger.toString()); + PingPeerMessage pingMessage = explorer.sendPing(challengedNode.getAddress(), 1, challengedNode); String messageId = pingMessage.getMessageId(); NodeChallenge challenge = new NodeChallenge(challengedNode, challenger, messageId); diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/PeerDiscoveryRequest.java b/rskj-core/src/main/java/co/rsk/net/discovery/PeerDiscoveryRequest.java index e1d01208776..8b732e504a4 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/PeerDiscoveryRequest.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/PeerDiscoveryRequest.java @@ -20,9 +20,11 @@ import co.rsk.net.discovery.message.DiscoveryMessageType; import co.rsk.net.discovery.message.PeerDiscoveryMessage; +import org.apache.commons.lang3.builder.ToStringBuilder; import org.ethereum.net.rlpx.Node; import java.net.InetSocketAddress; +import java.util.Optional; /** * Created by mario on 17/02/17. @@ -73,4 +75,14 @@ public boolean validateMessageResponse(InetSocketAddress responseAddress, PeerDi public boolean hasExpired() { return System.currentTimeMillis() > expirationDate; } + + @Override + public String toString() { + return new ToStringBuilder(this) + .append("messageId", this.messageId) + .append("message", this.message.toString()) + .append("address", this.address.toString()) + .append("relatedNode", Optional.ofNullable(this.relatedNode).map(Node::toString).orElse(null)) + .toString(); + } } diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java index 737c8bef154..c452b9af0f6 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java @@ -160,6 +160,10 @@ void setUDPChannel(UDPChannel udpChannel) { } synchronized void handleMessage(DiscoveryEvent event) { + logger.debug("co.rsk.net.discovery.PeerExplorer.handleMessage - Handling message:\n" + + "state: {},\n" + + "type: {},\n" + + "event:{}", state, event.getMessage().getMessageType(), event); if (state != ExecState.RUNNING) { logger.warn("Cannot handle message as current state is {}", state); return; @@ -182,7 +186,7 @@ synchronized void handleMessage(DiscoveryEvent event) { } if (type == DiscoveryMessageType.FIND_NODE) { - this.handleFindNode(event.getAddress(), (FindNodePeerMessage) event.getMessage()); + this.handleFindNode((FindNodePeerMessage) event.getMessage()); } if (type == DiscoveryMessageType.NEIGHBORS) { @@ -191,10 +195,14 @@ synchronized void handleMessage(DiscoveryEvent event) { } private void handlePingMessage(InetSocketAddress address, PingPeerMessage message) { - logger.debug("Handling ping message received from ip:[{}] port:[{}]", address.getHostName(), address.getPort()); this.sendPong(address, message); Node connectedNode = this.establishedConnections.get(message.getNodeId()); + logger.debug("co.rsk.net.discovery.PeerExplorer.handlePingMessage - Handling ping message:\n" + + "address: {},\n" + + "message: {},\n" + + "connectedNode: {}" + , address.toString(), message.toString(), Optional.ofNullable(connectedNode).map(Node::toString).orElse(null)); if (connectedNode == null) { this.sendPing(address, 1); @@ -204,8 +212,12 @@ private void handlePingMessage(InetSocketAddress address, PingPeerMessage messag } private void handlePong(InetSocketAddress pongAddress, PongPeerMessage message) { - logger.debug("Handling pong message received from ip:[{}] port:[{}]", pongAddress.getHostName(), pongAddress.getPort()); PeerDiscoveryRequest request = this.pendingPingRequests.get(message.getMessageId()); + logger.debug("co.rsk.net.discovery.PeerExplorer.handlePong - Handling pong message:\n" + + "pongAddress: {},\n" + + "message: {},\n" + + "request: {}" + , pongAddress.toString(), message.toString(), Optional.ofNullable(request).map(PeerDiscoveryRequest::toString).orElse(null)); if (request != null && request.validateMessageResponse(pongAddress, message)) { this.pendingPingRequests.remove(message.getMessageId()); @@ -216,10 +228,13 @@ private void handlePong(InetSocketAddress pongAddress, PongPeerMessage message) } } - private void handleFindNode(InetSocketAddress findNodeAddress, FindNodePeerMessage message) { - logger.debug("Handling find node message received from ip:[{}] port:[{}]", findNodeAddress.getHostName(), findNodeAddress.getPort()); + private void handleFindNode(FindNodePeerMessage message) { NodeID nodeId = message.getNodeId(); Node connectedNode = this.establishedConnections.get(nodeId); + logger.debug("co.rsk.net.discovery.PeerExplorer.handleFindNode - Handling find node message:\n" + + "message: {},\n" + + "connectedNode: {}" + , message.toString(), Optional.ofNullable(connectedNode).map(Node::toString).orElse(null)); if (connectedNode != null) { List nodesToSend = this.distanceTable.getClosestNodes(nodeId); @@ -230,8 +245,12 @@ private void handleFindNode(InetSocketAddress findNodeAddress, FindNodePeerMessa } private void handleNeighborsMessage(InetSocketAddress neighborsResponseAddress, NeighborsPeerMessage message) { - logger.debug("Handling neighbors message received from ip:[{}] port:[{}]", neighborsResponseAddress.getHostName(), neighborsResponseAddress.getPort()); Node connectedNode = this.establishedConnections.get(message.getNodeId()); + logger.debug("co.rsk.net.discovery.PeerExplorer.handleNeighborsMessage - Handling neighbors message:\n" + + "neighborsResponseAddress: {},\n" + + "message: {},\n" + + "connectedNode: {}" + , neighborsResponseAddress.toString(), message.toString(), Optional.ofNullable(connectedNode).map(Node::toString).orElse(null)); if (connectedNode != null) { logger.debug("Neighbors received from [{}]", connectedNode.getHexId()); @@ -257,6 +276,12 @@ private PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt) { synchronized PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt, Node node) { PingPeerMessage nodeMessage = checkPendingPeerToAddress(nodeAddress); + logger.debug("co.rsk.net.discovery.PeerExplorer.sendPing - Sending ping message:\n" + + "nodeAddress: {},\n" + + "attempt: {},\n" + + "node: {},\n" + + "nodeMessage: {}" + , nodeAddress.toString(), attempt, Optional.ofNullable(node).map(Node::toString).orElse(null), Optional.ofNullable(nodeMessage).map(PingPeerMessage::toString).orElse(null)); if (nodeMessage != null) { return nodeMessage; @@ -268,6 +293,9 @@ synchronized PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt localAddress.getAddress().getHostAddress(), localAddress.getPort(), id, this.key, this.networkId); + + logger.debug("co.rsk.net.discovery.PeerExplorer.sendPing - nodeMessage created: {}", nodeMessage.toString()); + udpChannel.write(new DiscoveryEvent(nodeMessage, nodeAddress)); PeerDiscoveryRequest request = PeerDiscoveryRequestBuilder.builder().messageId(id) @@ -276,13 +304,11 @@ synchronized PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt pendingPingRequests.put(nodeMessage.getMessageId(), request); - logger.debug("Ping message with id {} sent to ip:[{}] port:[{}] on attempt #{}", nodeMessage.getMessageId(), nodeAddress.getAddress().getHostAddress(), nodeAddress.getPort(), attempt); - return nodeMessage; } private void updateEntry(Node connectedNode) { - logger.trace("Updating node with id {}", connectedNode.getHexId()); + logger.trace("co.rsk.net.discovery.PeerExplorer.updateEntry - Updating node: {}", connectedNode.toString()); try { updateEntryLock.lock(); this.distanceTable.updateEntry(connectedNode); @@ -304,8 +330,14 @@ private PingPeerMessage checkPendingPeerToAddress(InetSocketAddress address) { private PongPeerMessage sendPong(InetSocketAddress nodeAddress, PingPeerMessage message) { InetSocketAddress localAddress = this.localNode.getAddress(); PongPeerMessage pongPeerMessage = PongPeerMessage.create(localAddress.getHostName(), localAddress.getPort(), message.getMessageId(), this.key, this.networkId); + + logger.debug("co.rsk.net.discovery.PeerExplorer.sendPong - Sending pong message:\n" + + "nodeAddress: {},\n" + + "message: {},\n" + + "pongPeerMessage: {}" + , nodeAddress.toString(), message.toString(), pongPeerMessage.toString()); + udpChannel.write(new DiscoveryEvent(pongPeerMessage, nodeAddress)); - logger.debug("Pong message with id {} sent to ip:[{}] port:[{}]", pongPeerMessage.getMessageId(), nodeAddress.getAddress().getHostAddress(), nodeAddress.getPort()); return pongPeerMessage; } @@ -315,23 +347,36 @@ FindNodePeerMessage sendFindNode(Node node) { InetSocketAddress nodeAddress = node.getAddress(); String id = UUID.randomUUID().toString(); FindNodePeerMessage findNodePeerMessage = FindNodePeerMessage.create(this.key.getNodeId(), id, this.key, this.networkId); + + logger.debug("co.rsk.net.discovery.PeerExplorer.sendFindNode - Sending find node message:\n" + + "node: {},\n" + + "nodeAddress: {},\n" + + "findNodePeerMessage: {},\n" + + "id: {}" + , node.toString(), nodeAddress.toString(), findNodePeerMessage.toString(), id); + udpChannel.write(new DiscoveryEvent(findNodePeerMessage, nodeAddress)); PeerDiscoveryRequest request = PeerDiscoveryRequestBuilder.builder().messageId(id).relatedNode(node) .message(findNodePeerMessage).address(nodeAddress).expectedResponse(DiscoveryMessageType.NEIGHBORS) .expirationPeriod(requestTimeout).build(); pendingFindNodeRequests.put(findNodePeerMessage.getMessageId(), request); - logger.debug("Find node message with id {} sent to ip:[{}] port:[{}]", findNodePeerMessage.getMessageId(), nodeAddress.getAddress().getHostAddress(), nodeAddress.getPort()); - return findNodePeerMessage; } private NeighborsPeerMessage sendNeighbors(InetSocketAddress nodeAddress, List nodes, String id) { List nodesToSend = getRandomizeLimitedList(nodes, MAX_NODES_PER_MSG, 5); NeighborsPeerMessage sendNodesMessage = NeighborsPeerMessage.create(nodesToSend, id, this.key, networkId); - udpChannel.write(new DiscoveryEvent(sendNodesMessage, nodeAddress)); - logger.debug(" [{}] Neighbors sent on message with id {} to ip:[{}] port:[{}]", nodesToSend.size(), sendNodesMessage.getMessageId(), nodeAddress.getAddress().getHostAddress(), nodeAddress.getPort()); + logger.debug("co.rsk.net.discovery.PeerExplorer.sendNeighbors - Sending neighbors message:\n" + + "nodeAddress: {},\n" + + "sendNodesMessage: {},\n" + + "id: {}\n" + + "nodes: {}\n" + + "nodesToSend: {}\n" + , nodeAddress.toString(), sendNodesMessage.toString(), id, nodes, nodesToSend); + + udpChannel.write(new DiscoveryEvent(sendNodesMessage, nodeAddress)); return sendNodesMessage; } @@ -347,7 +392,9 @@ private void purgeRequests() { } synchronized void clean() { - logger.trace("Cleaning expired requests"); + logger.trace("co.rsk.net.discovery.PeerExplorer.clean - Cleaning expired requests:\n" + + "state: {}", state); + if (state != ExecState.RUNNING) { logger.warn("Cannot clean as current state is {}", state); return; @@ -357,31 +404,47 @@ synchronized void clean() { } synchronized void update() { - logger.trace("Updating nodes list"); + logger.trace("co.rsk.net.discovery.PeerExplorer.update - Updating nodes list:\n" + + "state: {}", state); + if (state != ExecState.RUNNING) { logger.warn("Cannot update as current state is {}", state); return; } List closestNodes = this.distanceTable.getClosestNodes(this.localNode.getId()); + + logger.trace("co.rsk.net.discovery.PeerExplorer.update - closestNodes:\n" + + "closestNodes: {}", closestNodes); + this.askForMoreNodes(closestNodes); this.checkPeersPulse(closestNodes); } private void checkPeersPulse(List closestNodes) { List nodesToCheck = this.getRandomizeLimitedList(closestNodes, MAX_NODES_TO_CHECK, 10); - logger.trace("Checking peers pulse for {} nodes", nodesToCheck.size()); + + logger.trace("co.rsk.net.discovery.PeerExplorer.checkPeersPulse - Checking peers pulse for nodes:\n" + + "closestNodes: {}\n" + + "nodesToCheck: {}", closestNodes, nodesToCheck); + nodesToCheck.forEach(node -> sendPing(node.getAddress(), 1, node)); } private void askForMoreNodes(List closestNodes) { List nodesToAsk = getRandomizeLimitedList(closestNodes, MAX_NODES_TO_ASK, 5); - logger.trace("Asking for {} nodes", nodesToAsk.size()); + + logger.trace("co.rsk.net.discovery.PeerExplorer.askForMoreNodes - Asking for more nodes:\n" + + "closestNodes: {}\n" + + "nodesToAsk: {}", closestNodes, nodesToAsk); + nodesToAsk.forEach(this::sendFindNode); } private List removeExpiredRequests(Map pendingRequests) { - logger.trace("Removing expired requests"); + logger.trace("co.rsk.net.discovery.PeerExplorer.removeExpiredRequests - Removing expired requests:\n" + + "pendingRequests: {}", pendingRequests); + List requests = pendingRequests.values().stream() .filter(PeerDiscoveryRequest::hasExpired).collect(Collectors.toList()); requests.forEach(r -> pendingRequests.remove(r.getMessageId())); @@ -394,7 +457,9 @@ private void removeExpiredChallenges(List peerDiscoveryReq } private void resendExpiredPing(List peerDiscoveryRequests) { - logger.trace("Resending expired pings"); + logger.trace("co.rsk.net.discovery.PeerExplorer.resendExpiredPing - Resending expired pings:\n" + + "peerDiscoveryRequests: {}", peerDiscoveryRequests); + peerDiscoveryRequests.stream().filter(r -> r.getAttemptNumber() < RETRIES_COUNT) .forEach(r -> sendPing(r.getAddress(), r.getAttemptNumber() + 1, r.getRelatedNode())); } @@ -410,7 +475,8 @@ private void removeConnections(List expiredRequests) { } private void removeConnection(Node node) { - logger.debug("Removing node with id {}", node.getId()); + logger.debug("co.rsk.net.discovery.PeerExplorer.removeConnection - Removing node:\n" + + "node: {}", node.toString()); this.establishedConnections.remove(node.getId()); this.distanceTable.removeNode(node); this.knownHosts.remove(node.getAddressAsString()); @@ -419,6 +485,15 @@ private void removeConnection(Node node) { private void addConnection(PongPeerMessage message, String ip, int port) { Node senderNode = new Node(message.getNodeId().getID(), ip, port); boolean isLocalNode = StringUtils.equals(senderNode.getHexId(), this.localNode.getHexId()); + + logger.debug("co.rsk.net.discovery.PeerExplorer.addConnection - Adding node:\n" + + "message: {}\n" + + "ip: {}\n" + + "port: {}\n" + + "senderNode: {}\n" + + "isLocalNode: {}\n" + + "allowMultipleConnectionsPerHostPort: {}", message.toString(), ip, port, senderNode.toString(), isLocalNode, this.allowMultipleConnectionsPerHostPort); + if (isLocalNode) { return; } @@ -427,7 +502,6 @@ private void addConnection(PongPeerMessage message, String ip, int port) { disconnectPeerIfDuplicatedByNodeId(senderNode, ip, port); } - logger.debug("Adding node with id {}", senderNode.getId()); OperationResult result = this.distanceTable.addNode(senderNode); if (result.isSuccess()) { this.knownHosts.put(senderNode.getAddressAsString(), senderNode.getId()); @@ -435,7 +509,6 @@ private void addConnection(PongPeerMessage message, String ip, int port) { logger.debug("New Peer found or id changed: ip[{}] port[{}] id [{}]", ip, port, senderNode.getId()); } else { this.challengeManager.startChallenge(result.getAffectedEntry().getNode(), senderNode, this); - logger.debug("Challenge started for node with id {}", result.getAffectedEntry().getNode().getId()); } } diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java b/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java index fb1dcc2b277..93f28ea0b00 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java @@ -20,7 +20,6 @@ import co.rsk.net.NodeID; import org.ethereum.net.rlpx.Node; -import org.ethereum.util.ByteUtil; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -55,7 +54,9 @@ public synchronized OperationResult removeNode(Node node) { } public synchronized List getClosestNodes(NodeID nodeId) { - logger.trace("Getting closest nodes to id {}", ByteUtil.toHexString(nodeId.getID())); + logger.debug("co.rsk.net.discovery.table.NodeDistanceTable.getClosestNodes - Getting closest nodes:\n" + + "nodeId: {}", nodeId.toString()); + return getAllNodes().stream() .sorted(new NodeDistanceComparator(nodeId, this.distanceCalculator)) .collect(Collectors.toList()); From f094f3ac5d184a50bb48cc038d89df8bcf71e3da Mon Sep 17 00:00:00 2001 From: Reynold Morel Date: Wed, 25 Oct 2023 08:59:32 -0400 Subject: [PATCH 04/17] Add more logs --- .../net/discovery/PeerDiscoveryRequest.java | 3 +- .../co/rsk/net/discovery/PeerExplorer.java | 139 +++++++++++------- .../rsk/net/discovery/table/BucketEntry.java | 9 ++ .../net/discovery/table/OperationResult.java | 10 ++ 4 files changed, 105 insertions(+), 56 deletions(-) diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/PeerDiscoveryRequest.java b/rskj-core/src/main/java/co/rsk/net/discovery/PeerDiscoveryRequest.java index 8b732e504a4..8346e7c8178 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/PeerDiscoveryRequest.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/PeerDiscoveryRequest.java @@ -24,7 +24,6 @@ import org.ethereum.net.rlpx.Node; import java.net.InetSocketAddress; -import java.util.Optional; /** * Created by mario on 17/02/17. @@ -82,7 +81,7 @@ public String toString() { .append("messageId", this.messageId) .append("message", this.message.toString()) .append("address", this.address.toString()) - .append("relatedNode", Optional.ofNullable(this.relatedNode).map(Node::toString).orElse(null)) + .append("relatedNode", this.relatedNode == null ? null : this.relatedNode.toString()) .toString(); } } diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java index c452b9af0f6..41b3538b5df 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java @@ -163,7 +163,8 @@ synchronized void handleMessage(DiscoveryEvent event) { logger.debug("co.rsk.net.discovery.PeerExplorer.handleMessage - Handling message:\n" + "state: {},\n" + "type: {},\n" + - "event:{}", state, event.getMessage().getMessageType(), event); + "networkId:{}", state, event.getMessage().getMessageType(), event.getMessage().getNetworkId().getAsInt()); + if (state != ExecState.RUNNING) { logger.warn("Cannot handle message as current state is {}", state); return; @@ -195,14 +196,16 @@ synchronized void handleMessage(DiscoveryEvent event) { } private void handlePingMessage(InetSocketAddress address, PingPeerMessage message) { + logger.debug("co.rsk.net.discovery.PeerExplorer.handlePingMessage - Handling ping message:\n" + + "address: {},\n" + + "nodeId: {}" + , address, message.getNodeId()); + this.sendPong(address, message); Node connectedNode = this.establishedConnections.get(message.getNodeId()); - logger.debug("co.rsk.net.discovery.PeerExplorer.handlePingMessage - Handling ping message:\n" + - "address: {},\n" + - "message: {},\n" + - "connectedNode: {}" - , address.toString(), message.toString(), Optional.ofNullable(connectedNode).map(Node::toString).orElse(null)); + + logger.debug("co.rsk.net.discovery.PeerExplorer.handlePingMessage - Get connectedNode result: {}", connectedNode); if (connectedNode == null) { this.sendPing(address, 1); @@ -212,12 +215,14 @@ private void handlePingMessage(InetSocketAddress address, PingPeerMessage messag } private void handlePong(InetSocketAddress pongAddress, PongPeerMessage message) { - PeerDiscoveryRequest request = this.pendingPingRequests.get(message.getMessageId()); logger.debug("co.rsk.net.discovery.PeerExplorer.handlePong - Handling pong message:\n" + "pongAddress: {},\n" + - "message: {},\n" + - "request: {}" - , pongAddress.toString(), message.toString(), Optional.ofNullable(request).map(PeerDiscoveryRequest::toString).orElse(null)); + "messageId: {}" + , pongAddress, message.getMessageId()); + + PeerDiscoveryRequest request = this.pendingPingRequests.get(message.getMessageId()); + + logger.debug("co.rsk.net.discovery.PeerExplorer.handlePong - Get request result: {}", request); if (request != null && request.validateMessageResponse(pongAddress, message)) { this.pendingPingRequests.remove(message.getMessageId()); @@ -229,12 +234,15 @@ private void handlePong(InetSocketAddress pongAddress, PongPeerMessage message) } private void handleFindNode(FindNodePeerMessage message) { + logger.debug("co.rsk.net.discovery.PeerExplorer.handleFindNode - Handling find node message:\n" + + "nodeId: {},\n" + + "messageId: {}" + , message.getNodeId(), message.getMessageId()); + NodeID nodeId = message.getNodeId(); Node connectedNode = this.establishedConnections.get(nodeId); - logger.debug("co.rsk.net.discovery.PeerExplorer.handleFindNode - Handling find node message:\n" + - "message: {},\n" + - "connectedNode: {}" - , message.toString(), Optional.ofNullable(connectedNode).map(Node::toString).orElse(null)); + + logger.debug("co.rsk.net.discovery.PeerExplorer.handleFindNode - Get connectedNode result: {}", connectedNode); if (connectedNode != null) { List nodesToSend = this.distanceTable.getClosestNodes(nodeId); @@ -245,12 +253,17 @@ private void handleFindNode(FindNodePeerMessage message) { } private void handleNeighborsMessage(InetSocketAddress neighborsResponseAddress, NeighborsPeerMessage message) { - Node connectedNode = this.establishedConnections.get(message.getNodeId()); logger.debug("co.rsk.net.discovery.PeerExplorer.handleNeighborsMessage - Handling neighbors message:\n" + "neighborsResponseAddress: {},\n" + - "message: {},\n" + - "connectedNode: {}" - , neighborsResponseAddress.toString(), message.toString(), Optional.ofNullable(connectedNode).map(Node::toString).orElse(null)); + "nodeId: {},\n" + + "messageId: {}\n" + + "nodesCount: {}\n" + + "nodes: {}" + , neighborsResponseAddress, message.getNodeId(), message.getMessageId(), message.countNodes(), message.getNodes()); + + Node connectedNode = this.establishedConnections.get(message.getNodeId()); + + logger.debug("co.rsk.net.discovery.PeerExplorer.handleNeighborsMessage - Get connectedNode result: {}", connectedNode); if (connectedNode != null) { logger.debug("Neighbors received from [{}]", connectedNode.getHexId()); @@ -275,13 +288,15 @@ private PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt) { } synchronized PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt, Node node) { - PingPeerMessage nodeMessage = checkPendingPeerToAddress(nodeAddress); logger.debug("co.rsk.net.discovery.PeerExplorer.sendPing - Sending ping message:\n" + "nodeAddress: {},\n" + "attempt: {},\n" + - "node: {},\n" + - "nodeMessage: {}" - , nodeAddress.toString(), attempt, Optional.ofNullable(node).map(Node::toString).orElse(null), Optional.ofNullable(nodeMessage).map(PingPeerMessage::toString).orElse(null)); + "node: {}" + , nodeAddress, attempt, node == null ? null : node.toString()); + + PingPeerMessage nodeMessage = checkPendingPeerToAddress(nodeAddress); + + logger.debug("co.rsk.net.discovery.PeerExplorer.sendPing - Get nodeMessage result: {}", nodeMessage); if (nodeMessage != null) { return nodeMessage; @@ -294,7 +309,7 @@ synchronized PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt localAddress.getPort(), id, this.key, this.networkId); - logger.debug("co.rsk.net.discovery.PeerExplorer.sendPing - nodeMessage created: {}", nodeMessage.toString()); + logger.debug("co.rsk.net.discovery.PeerExplorer.sendPing - nodeMessage created: {}", nodeMessage); udpChannel.write(new DiscoveryEvent(nodeMessage, nodeAddress)); @@ -308,7 +323,7 @@ synchronized PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt } private void updateEntry(Node connectedNode) { - logger.trace("co.rsk.net.discovery.PeerExplorer.updateEntry - Updating node: {}", connectedNode.toString()); + logger.trace("co.rsk.net.discovery.PeerExplorer.updateEntry - Updating node: {}", connectedNode); try { updateEntryLock.lock(); this.distanceTable.updateEntry(connectedNode); @@ -328,14 +343,15 @@ private PingPeerMessage checkPendingPeerToAddress(InetSocketAddress address) { } private PongPeerMessage sendPong(InetSocketAddress nodeAddress, PingPeerMessage message) { + logger.debug("co.rsk.net.discovery.PeerExplorer.sendPong - Sending pong message:\n" + + "nodeAddress: {},\n" + + "messageId: {}" + , nodeAddress, message.getMessageId()); + InetSocketAddress localAddress = this.localNode.getAddress(); PongPeerMessage pongPeerMessage = PongPeerMessage.create(localAddress.getHostName(), localAddress.getPort(), message.getMessageId(), this.key, this.networkId); - logger.debug("co.rsk.net.discovery.PeerExplorer.sendPong - Sending pong message:\n" + - "nodeAddress: {},\n" + - "message: {},\n" + - "pongPeerMessage: {}" - , nodeAddress.toString(), message.toString(), pongPeerMessage.toString()); + logger.debug("co.rsk.net.discovery.PeerExplorer.sendPong - pongPeerMessage created: {}", pongPeerMessage); udpChannel.write(new DiscoveryEvent(pongPeerMessage, nodeAddress)); @@ -344,37 +360,42 @@ private PongPeerMessage sendPong(InetSocketAddress nodeAddress, PingPeerMessage @VisibleForTesting FindNodePeerMessage sendFindNode(Node node) { + logger.debug("co.rsk.net.discovery.PeerExplorer.sendFindNode - Sending find node message:\n" + + "nodeAddress: {}" + , node.getAddress()); + InetSocketAddress nodeAddress = node.getAddress(); String id = UUID.randomUUID().toString(); FindNodePeerMessage findNodePeerMessage = FindNodePeerMessage.create(this.key.getNodeId(), id, this.key, this.networkId); - logger.debug("co.rsk.net.discovery.PeerExplorer.sendFindNode - Sending find node message:\n" + - "node: {},\n" + - "nodeAddress: {},\n" + - "findNodePeerMessage: {},\n" + - "id: {}" - , node.toString(), nodeAddress.toString(), findNodePeerMessage.toString(), id); + logger.debug("co.rsk.net.discovery.PeerExplorer.sendFindNode - findNodePeerMessage created: {}", findNodePeerMessage); udpChannel.write(new DiscoveryEvent(findNodePeerMessage, nodeAddress)); PeerDiscoveryRequest request = PeerDiscoveryRequestBuilder.builder().messageId(id).relatedNode(node) .message(findNodePeerMessage).address(nodeAddress).expectedResponse(DiscoveryMessageType.NEIGHBORS) .expirationPeriod(requestTimeout).build(); + + logger.debug("co.rsk.net.discovery.PeerExplorer.sendFindNode - request created: {}", request); + pendingFindNodeRequests.put(findNodePeerMessage.getMessageId(), request); return findNodePeerMessage; } private NeighborsPeerMessage sendNeighbors(InetSocketAddress nodeAddress, List nodes, String id) { - List nodesToSend = getRandomizeLimitedList(nodes, MAX_NODES_PER_MSG, 5); - NeighborsPeerMessage sendNodesMessage = NeighborsPeerMessage.create(nodesToSend, id, this.key, networkId); - logger.debug("co.rsk.net.discovery.PeerExplorer.sendNeighbors - Sending neighbors message:\n" + "nodeAddress: {},\n" + - "sendNodesMessage: {},\n" + "id: {}\n" + - "nodes: {}\n" + - "nodesToSend: {}\n" - , nodeAddress.toString(), sendNodesMessage.toString(), id, nodes, nodesToSend); + "nodes: {}" + , nodeAddress, id, nodes); + + List nodesToSend = getRandomizeLimitedList(nodes, MAX_NODES_PER_MSG, 5); + + logger.debug("co.rsk.net.discovery.PeerExplorer.sendNeighbors - nodesToSend: {}", nodesToSend); + + NeighborsPeerMessage sendNodesMessage = NeighborsPeerMessage.create(nodesToSend, id, this.key, networkId); + + logger.debug("co.rsk.net.discovery.PeerExplorer.sendNeighbors - sendNodesMessage created: {}", sendNodesMessage); udpChannel.write(new DiscoveryEvent(sendNodesMessage, nodeAddress)); @@ -422,21 +443,23 @@ synchronized void update() { } private void checkPeersPulse(List closestNodes) { + logger.trace("co.rsk.net.discovery.PeerExplorer.checkPeersPulse - Checking peers pulse for nodes:\n" + + "closestNodes: {}", closestNodes); + List nodesToCheck = this.getRandomizeLimitedList(closestNodes, MAX_NODES_TO_CHECK, 10); - logger.trace("co.rsk.net.discovery.PeerExplorer.checkPeersPulse - Checking peers pulse for nodes:\n" + - "closestNodes: {}\n" + - "nodesToCheck: {}", closestNodes, nodesToCheck); + logger.trace("co.rsk.net.discovery.PeerExplorer.checkPeersPulse - nodesToCheck: {}", nodesToCheck); nodesToCheck.forEach(node -> sendPing(node.getAddress(), 1, node)); } private void askForMoreNodes(List closestNodes) { + logger.trace("co.rsk.net.discovery.PeerExplorer.askForMoreNodes - Asking for more nodes:\n" + + "closestNodes: {}", closestNodes); + List nodesToAsk = getRandomizeLimitedList(closestNodes, MAX_NODES_TO_ASK, 5); - logger.trace("co.rsk.net.discovery.PeerExplorer.askForMoreNodes - Asking for more nodes:\n" + - "closestNodes: {}\n" + - "nodesToAsk: {}", closestNodes, nodesToAsk); + logger.trace("co.rsk.net.discovery.PeerExplorer.askForMoreNodes - nodesToAsk: {}", nodesToAsk); nodesToAsk.forEach(this::sendFindNode); } @@ -449,6 +472,8 @@ private List removeExpiredRequests(Map pendingRequests.remove(r.getMessageId())); + logger.trace("co.rsk.net.discovery.PeerExplorer.removeExpiredRequests - requests removed: {}", requests); + return requests; } @@ -476,23 +501,26 @@ private void removeConnections(List expiredRequests) { private void removeConnection(Node node) { logger.debug("co.rsk.net.discovery.PeerExplorer.removeConnection - Removing node:\n" + - "node: {}", node.toString()); + "nodeId: {}\n" + + "nodeAddress: {}", node.getHexId(), node.getAddressAsString()); this.establishedConnections.remove(node.getId()); this.distanceTable.removeNode(node); this.knownHosts.remove(node.getAddressAsString()); } private void addConnection(PongPeerMessage message, String ip, int port) { - Node senderNode = new Node(message.getNodeId().getID(), ip, port); - boolean isLocalNode = StringUtils.equals(senderNode.getHexId(), this.localNode.getHexId()); - logger.debug("co.rsk.net.discovery.PeerExplorer.addConnection - Adding node:\n" + "message: {}\n" + "ip: {}\n" + "port: {}\n" + + "allowMultipleConnectionsPerHostPort: {}", message.toString(), ip, port, this.allowMultipleConnectionsPerHostPort); + + Node senderNode = new Node(message.getNodeId().getID(), ip, port); + boolean isLocalNode = StringUtils.equals(senderNode.getHexId(), this.localNode.getHexId()); + + logger.debug("co.rsk.net.discovery.PeerExplorer.addConnection\n" + "senderNode: {}\n" + - "isLocalNode: {}\n" + - "allowMultipleConnectionsPerHostPort: {}", message.toString(), ip, port, senderNode.toString(), isLocalNode, this.allowMultipleConnectionsPerHostPort); + "isLocalNode: {}", senderNode, isLocalNode); if (isLocalNode) { return; @@ -503,6 +531,9 @@ private void addConnection(PongPeerMessage message, String ip, int port) { } OperationResult result = this.distanceTable.addNode(senderNode); + + logger.debug("co.rsk.net.discovery.PeerExplorer.addConnection - result: {}", result); + if (result.isSuccess()) { this.knownHosts.put(senderNode.getAddressAsString(), senderNode.getId()); this.establishedConnections.put(senderNode.getId(), senderNode); diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/table/BucketEntry.java b/rskj-core/src/main/java/co/rsk/net/discovery/table/BucketEntry.java index c84e4ac5d58..89615c8e340 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/table/BucketEntry.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/table/BucketEntry.java @@ -18,6 +18,7 @@ package co.rsk.net.discovery.table; +import org.apache.commons.lang3.builder.ToStringBuilder; import org.ethereum.net.rlpx.Node; /** @@ -43,4 +44,12 @@ public long lastSeen() { public void updateTime() { this.lastSeenTime = System.currentTimeMillis(); } + + @Override + public String toString() { + return new ToStringBuilder(this) + .append("node", node) + .append("lastSeenTime", lastSeenTime) + .toString(); + } } diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/table/OperationResult.java b/rskj-core/src/main/java/co/rsk/net/discovery/table/OperationResult.java index 6b273de8a33..c797a17b41e 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/table/OperationResult.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/table/OperationResult.java @@ -18,6 +18,8 @@ package co.rsk.net.discovery.table; +import org.apache.commons.lang3.builder.ToStringBuilder; + /** * Created by mario on 21/02/17. */ @@ -38,4 +40,12 @@ public boolean isSuccess() { public BucketEntry getAffectedEntry() { return affectedEntry; } + + @Override + public String toString() { + return new ToStringBuilder(this) + .append("success", success) + .append("affectedEntry", affectedEntry.toString()) + .toString(); + } } From 5013140c7c16ec5c6eaa1eafd1ca2a9e6751be2e Mon Sep 17 00:00:00 2001 From: Reynold Morel Date: Wed, 25 Oct 2023 09:37:17 -0400 Subject: [PATCH 05/17] Fix CodeQL errors --- .../co/rsk/net/discovery/PeerExplorer.java | 45 +++++++++++-------- 1 file changed, 27 insertions(+), 18 deletions(-) diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java index 41b3538b5df..931d7cacb91 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java @@ -197,9 +197,10 @@ synchronized void handleMessage(DiscoveryEvent event) { private void handlePingMessage(InetSocketAddress address, PingPeerMessage message) { logger.debug("co.rsk.net.discovery.PeerExplorer.handlePingMessage - Handling ping message:\n" + - "address: {},\n" + + "address hostName: {},\n" + + "address port: {},\n" + "nodeId: {}" - , address, message.getNodeId()); + , address.getHostName(), address.getPort(), message.getNodeId()); this.sendPong(address, message); @@ -216,9 +217,10 @@ private void handlePingMessage(InetSocketAddress address, PingPeerMessage messag private void handlePong(InetSocketAddress pongAddress, PongPeerMessage message) { logger.debug("co.rsk.net.discovery.PeerExplorer.handlePong - Handling pong message:\n" + - "pongAddress: {},\n" + + "pongAddress hostName: {},\n" + + "pongAddress port: {},\n" + "messageId: {}" - , pongAddress, message.getMessageId()); + , pongAddress.getHostName(), pongAddress.getPort(), message.getMessageId()); PeerDiscoveryRequest request = this.pendingPingRequests.get(message.getMessageId()); @@ -254,12 +256,13 @@ private void handleFindNode(FindNodePeerMessage message) { private void handleNeighborsMessage(InetSocketAddress neighborsResponseAddress, NeighborsPeerMessage message) { logger.debug("co.rsk.net.discovery.PeerExplorer.handleNeighborsMessage - Handling neighbors message:\n" + - "neighborsResponseAddress: {},\n" + + "neighborsResponseAddress hostName: {},\n" + + "neighborsResponseAddress port: {},\n" + "nodeId: {},\n" + "messageId: {}\n" + "nodesCount: {}\n" + "nodes: {}" - , neighborsResponseAddress, message.getNodeId(), message.getMessageId(), message.countNodes(), message.getNodes()); + , neighborsResponseAddress.getHostName(), neighborsResponseAddress.getPort(), message.getNodeId(), message.getMessageId(), message.countNodes(), message.getNodes()); Node connectedNode = this.establishedConnections.get(message.getNodeId()); @@ -289,10 +292,11 @@ private PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt) { synchronized PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt, Node node) { logger.debug("co.rsk.net.discovery.PeerExplorer.sendPing - Sending ping message:\n" + - "nodeAddress: {},\n" + + "nodeAddress hostName: {},\n" + + "nodeAddress port: {},\n" + "attempt: {},\n" + "node: {}" - , nodeAddress, attempt, node == null ? null : node.toString()); + , nodeAddress.getHostName(), nodeAddress.getPort(), attempt, node == null ? null : node.toString()); PingPeerMessage nodeMessage = checkPendingPeerToAddress(nodeAddress); @@ -323,7 +327,7 @@ synchronized PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt } private void updateEntry(Node connectedNode) { - logger.trace("co.rsk.net.discovery.PeerExplorer.updateEntry - Updating node: {}", connectedNode); + logger.trace("co.rsk.net.discovery.PeerExplorer.updateEntry - Updating node {}", connectedNode.getHexId()); try { updateEntryLock.lock(); this.distanceTable.updateEntry(connectedNode); @@ -344,9 +348,10 @@ private PingPeerMessage checkPendingPeerToAddress(InetSocketAddress address) { private PongPeerMessage sendPong(InetSocketAddress nodeAddress, PingPeerMessage message) { logger.debug("co.rsk.net.discovery.PeerExplorer.sendPong - Sending pong message:\n" + - "nodeAddress: {},\n" + + "nodeAddress hostName: {},\n" + + "nodeAddress port: {},\n" + "messageId: {}" - , nodeAddress, message.getMessageId()); + , nodeAddress.getHostName(), nodeAddress.getPort(), message.getMessageId()); InetSocketAddress localAddress = this.localNode.getAddress(); PongPeerMessage pongPeerMessage = PongPeerMessage.create(localAddress.getHostName(), localAddress.getPort(), message.getMessageId(), this.key, this.networkId); @@ -361,8 +366,9 @@ private PongPeerMessage sendPong(InetSocketAddress nodeAddress, PingPeerMessage @VisibleForTesting FindNodePeerMessage sendFindNode(Node node) { logger.debug("co.rsk.net.discovery.PeerExplorer.sendFindNode - Sending find node message:\n" + - "nodeAddress: {}" - , node.getAddress()); + "nodeAddress hostName: {}\n" + + "nodeAddress hostName: {}" + , node.getAddress().getHostName(), node.getAddress().getPort()); InetSocketAddress nodeAddress = node.getAddress(); String id = UUID.randomUUID().toString(); @@ -384,10 +390,11 @@ FindNodePeerMessage sendFindNode(Node node) { private NeighborsPeerMessage sendNeighbors(InetSocketAddress nodeAddress, List nodes, String id) { logger.debug("co.rsk.net.discovery.PeerExplorer.sendNeighbors - Sending neighbors message:\n" + - "nodeAddress: {},\n" + + "nodeAddress hostName: {},\n" + + "nodeAddress port: {},\n" + "id: {}\n" + "nodes: {}" - , nodeAddress, id, nodes); + , nodeAddress.getHostName(), nodeAddress.getPort(), id, nodes); List nodesToSend = getRandomizeLimitedList(nodes, MAX_NODES_PER_MSG, 5); @@ -502,7 +509,9 @@ private void removeConnections(List expiredRequests) { private void removeConnection(Node node) { logger.debug("co.rsk.net.discovery.PeerExplorer.removeConnection - Removing node:\n" + "nodeId: {}\n" + - "nodeAddress: {}", node.getHexId(), node.getAddressAsString()); + "nodeAddress hostName: {}\n" + + "nodeAddress port: {}", node.getHexId(), node.getAddress().getHostName(), node.getAddress().getPort()); + this.establishedConnections.remove(node.getId()); this.distanceTable.removeNode(node); this.knownHosts.remove(node.getAddressAsString()); @@ -510,10 +519,10 @@ private void removeConnection(Node node) { private void addConnection(PongPeerMessage message, String ip, int port) { logger.debug("co.rsk.net.discovery.PeerExplorer.addConnection - Adding node:\n" + - "message: {}\n" + + "messageId: {}\n" + "ip: {}\n" + "port: {}\n" + - "allowMultipleConnectionsPerHostPort: {}", message.toString(), ip, port, this.allowMultipleConnectionsPerHostPort); + "allowMultipleConnectionsPerHostPort: {}", message.getMessageId(), ip, port, this.allowMultipleConnectionsPerHostPort); Node senderNode = new Node(message.getNodeId().getID(), ip, port); boolean isLocalNode = StringUtils.equals(senderNode.getHexId(), this.localNode.getHexId()); From 92d07e743a0923d0c4aeb3a23c7df96bf5ea973b Mon Sep 17 00:00:00 2001 From: Reynold Morel Date: Mon, 30 Oct 2023 16:02:17 -0400 Subject: [PATCH 06/17] Remove full method path and line breaks from messages --- .../co/rsk/net/discovery/DiscoveryEvent.java | 4 +- .../net/discovery/NodeChallengeManager.java | 4 +- .../net/discovery/PeerDiscoveryRequest.java | 6 +- .../co/rsk/net/discovery/PeerExplorer.java | 185 ++++++++---------- .../discovery/table/NodeDistanceTable.java | 3 +- .../net/discovery/table/OperationResult.java | 2 +- 6 files changed, 88 insertions(+), 116 deletions(-) diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/DiscoveryEvent.java b/rskj-core/src/main/java/co/rsk/net/discovery/DiscoveryEvent.java index 7ab0f394676..a083c4e54fe 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/DiscoveryEvent.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/DiscoveryEvent.java @@ -43,8 +43,8 @@ public InetSocketAddress getAddress() { @Override public String toString() { return new ToStringBuilder(this) - .append("message", this.message.toString()) - .append("address", this.address.toString()) + .append("message", this.message) + .append("address", this.address) .toString(); } } diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java b/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java index ed26ba25698..21ffd765d6f 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java @@ -36,9 +36,7 @@ public class NodeChallengeManager { private Map activeChallenges = new ConcurrentHashMap<>(); public NodeChallenge startChallenge(Node challengedNode, Node challenger, PeerExplorer explorer) { - logger.debug("co.rsk.net.discovery.NodeChallengeManager.startChallenge - Starting challenge for node:\n" + - "challengedNode: {}\n" + - "challenger: {}", challengedNode.toString(), challenger.toString()); + logger.debug("startChallenge - Starting challenge for node: [{}] by challenger: [{}]", challengedNode.toString(), challenger.toString()); PingPeerMessage pingMessage = explorer.sendPing(challengedNode.getAddress(), 1, challengedNode); String messageId = pingMessage.getMessageId(); diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/PeerDiscoveryRequest.java b/rskj-core/src/main/java/co/rsk/net/discovery/PeerDiscoveryRequest.java index 8346e7c8178..9bd7ae77fa4 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/PeerDiscoveryRequest.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/PeerDiscoveryRequest.java @@ -79,9 +79,9 @@ public boolean hasExpired() { public String toString() { return new ToStringBuilder(this) .append("messageId", this.messageId) - .append("message", this.message.toString()) - .append("address", this.address.toString()) - .append("relatedNode", this.relatedNode == null ? null : this.relatedNode.toString()) + .append("message", this.message) + .append("address", this.address) + .append("relatedNode", this.relatedNode) .toString(); } } diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java index 931d7cacb91..4019afbe048 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java @@ -160,10 +160,11 @@ void setUDPChannel(UDPChannel udpChannel) { } synchronized void handleMessage(DiscoveryEvent event) { - logger.debug("co.rsk.net.discovery.PeerExplorer.handleMessage - Handling message:\n" + - "state: {},\n" + - "type: {},\n" + - "networkId:{}", state, event.getMessage().getMessageType(), event.getMessage().getNetworkId().getAsInt()); + logger.debug("handleMessage - Handling message with " + + "state: [{}], " + + "type: [{}], " + + "networkId: [{}]", + state, event.getMessage().getMessageType(), event.getMessage().getNetworkId().getAsInt()); if (state != ExecState.RUNNING) { logger.warn("Cannot handle message as current state is {}", state); @@ -175,7 +176,8 @@ synchronized void handleMessage(DiscoveryEvent event) { //have a networkId in the message yet, then just let them through, for now. if (event.getMessage().getNetworkId().isPresent() && event.getMessage().getNetworkId().getAsInt() != this.networkId) { - logger.debug("Message ignored due to different network id {}", event.getMessage().getNetworkId().getAsInt()); + logger.debug("handleMessage - Message ignored because network id [{}] is different from [{}]", + event.getMessage().getNetworkId().getAsInt(), this.networkId); return; } if (type == DiscoveryMessageType.PING) { @@ -196,17 +198,15 @@ synchronized void handleMessage(DiscoveryEvent event) { } private void handlePingMessage(InetSocketAddress address, PingPeerMessage message) { - logger.debug("co.rsk.net.discovery.PeerExplorer.handlePingMessage - Handling ping message:\n" + - "address hostName: {},\n" + - "address port: {},\n" + - "nodeId: {}" - , address.getHostName(), address.getPort(), message.getNodeId()); - this.sendPong(address, message); - Node connectedNode = this.establishedConnections.get(message.getNodeId()); - logger.debug("co.rsk.net.discovery.PeerExplorer.handlePingMessage - Get connectedNode result: {}", connectedNode); + logger.debug("handlePingMessage - Handling ping message with " + + "address hostName: [{}], " + + "address port: [{}], " + + "nodeId: [{}], " + + "connectedNode: [{}]" + , address.getHostName(), address.getPort(), message.getNodeId(), connectedNode); if (connectedNode == null) { this.sendPing(address, 1); @@ -216,15 +216,14 @@ private void handlePingMessage(InetSocketAddress address, PingPeerMessage messag } private void handlePong(InetSocketAddress pongAddress, PongPeerMessage message) { - logger.debug("co.rsk.net.discovery.PeerExplorer.handlePong - Handling pong message:\n" + - "pongAddress hostName: {},\n" + - "pongAddress port: {},\n" + - "messageId: {}" - , pongAddress.getHostName(), pongAddress.getPort(), message.getMessageId()); - PeerDiscoveryRequest request = this.pendingPingRequests.get(message.getMessageId()); - logger.debug("co.rsk.net.discovery.PeerExplorer.handlePong - Get request result: {}", request); + logger.debug("handlePong - Handling pong message with " + + "pongAddress hostName: [{}], " + + "pongAddress port: [{}], " + + "messageId: [{}], " + + "request: [{}]" + , pongAddress.getHostName(), pongAddress.getPort(), message.getMessageId(), request); if (request != null && request.validateMessageResponse(pongAddress, message)) { this.pendingPingRequests.remove(message.getMessageId()); @@ -236,15 +235,14 @@ private void handlePong(InetSocketAddress pongAddress, PongPeerMessage message) } private void handleFindNode(FindNodePeerMessage message) { - logger.debug("co.rsk.net.discovery.PeerExplorer.handleFindNode - Handling find node message:\n" + - "nodeId: {},\n" + - "messageId: {}" - , message.getNodeId(), message.getMessageId()); - NodeID nodeId = message.getNodeId(); Node connectedNode = this.establishedConnections.get(nodeId); - logger.debug("co.rsk.net.discovery.PeerExplorer.handleFindNode - Get connectedNode result: {}", connectedNode); + logger.debug("handleFindNode - Handling find node message with " + + "nodeId: {}, " + + "messageId: {}, " + + "connectedNode: {}" + , message.getNodeId(), message.getMessageId(), connectedNode); if (connectedNode != null) { List nodesToSend = this.distanceTable.getClosestNodes(nodeId); @@ -255,18 +253,18 @@ private void handleFindNode(FindNodePeerMessage message) { } private void handleNeighborsMessage(InetSocketAddress neighborsResponseAddress, NeighborsPeerMessage message) { - logger.debug("co.rsk.net.discovery.PeerExplorer.handleNeighborsMessage - Handling neighbors message:\n" + - "neighborsResponseAddress hostName: {},\n" + - "neighborsResponseAddress port: {},\n" + - "nodeId: {},\n" + - "messageId: {}\n" + - "nodesCount: {}\n" + - "nodes: {}" - , neighborsResponseAddress.getHostName(), neighborsResponseAddress.getPort(), message.getNodeId(), message.getMessageId(), message.countNodes(), message.getNodes()); - Node connectedNode = this.establishedConnections.get(message.getNodeId()); - logger.debug("co.rsk.net.discovery.PeerExplorer.handleNeighborsMessage - Get connectedNode result: {}", connectedNode); + logger.debug("handleNeighborsMessage - Handling neighbors message with " + + "neighborsResponseAddress hostName: {}," + + "neighborsResponseAddress port: [{}]," + + "nodeId: [{}]," + + "messageId: [{}], " + + "nodesCount: [{}], " + + "nodes: [{}], " + + "connectedNode: [{}]" + , neighborsResponseAddress.getHostName(), neighborsResponseAddress.getPort(), message.getNodeId(), + message.getMessageId(), message.countNodes(), message.getNodes(), connectedNode); if (connectedNode != null) { logger.debug("Neighbors received from [{}]", connectedNode.getHexId()); @@ -291,16 +289,15 @@ private PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt) { } synchronized PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt, Node node) { - logger.debug("co.rsk.net.discovery.PeerExplorer.sendPing - Sending ping message:\n" + - "nodeAddress hostName: {},\n" + - "nodeAddress port: {},\n" + - "attempt: {},\n" + - "node: {}" - , nodeAddress.getHostName(), nodeAddress.getPort(), attempt, node == null ? null : node.toString()); - PingPeerMessage nodeMessage = checkPendingPeerToAddress(nodeAddress); - logger.debug("co.rsk.net.discovery.PeerExplorer.sendPing - Get nodeMessage result: {}", nodeMessage); + logger.debug("sendPing - Sending ping message to " + + "nodeAddress hostName: [{}], " + + "nodeAddress port: [{}], " + + "attempt: [{}], " + + "node: [{}], " + + "nodeMessage: [{}]" + , nodeAddress.getHostName(), nodeAddress.getPort(), attempt, node, nodeMessage); if (nodeMessage != null) { return nodeMessage; @@ -313,7 +310,7 @@ synchronized PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt localAddress.getPort(), id, this.key, this.networkId); - logger.debug("co.rsk.net.discovery.PeerExplorer.sendPing - nodeMessage created: {}", nodeMessage); + logger.debug("sendPing - nodeMessage created: [{}]", nodeMessage); udpChannel.write(new DiscoveryEvent(nodeMessage, nodeAddress)); @@ -327,7 +324,7 @@ synchronized PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt } private void updateEntry(Node connectedNode) { - logger.trace("co.rsk.net.discovery.PeerExplorer.updateEntry - Updating node {}", connectedNode.getHexId()); + logger.trace("updateEntry - Updating node [{}]", connectedNode.getHexId()); try { updateEntryLock.lock(); this.distanceTable.updateEntry(connectedNode); @@ -347,16 +344,15 @@ private PingPeerMessage checkPendingPeerToAddress(InetSocketAddress address) { } private PongPeerMessage sendPong(InetSocketAddress nodeAddress, PingPeerMessage message) { - logger.debug("co.rsk.net.discovery.PeerExplorer.sendPong - Sending pong message:\n" + - "nodeAddress hostName: {},\n" + - "nodeAddress port: {},\n" + - "messageId: {}" - , nodeAddress.getHostName(), nodeAddress.getPort(), message.getMessageId()); - InetSocketAddress localAddress = this.localNode.getAddress(); PongPeerMessage pongPeerMessage = PongPeerMessage.create(localAddress.getHostName(), localAddress.getPort(), message.getMessageId(), this.key, this.networkId); - logger.debug("co.rsk.net.discovery.PeerExplorer.sendPong - pongPeerMessage created: {}", pongPeerMessage); + logger.debug("sendPong - Sending pong message to " + + "nodeAddress hostName: [{}], " + + "nodeAddress port: [{}], " + + "messageId: [{}], " + + "pongPeerMessage: [{}]" + , nodeAddress.getHostName(), nodeAddress.getPort(), message.getMessageId(), pongPeerMessage); udpChannel.write(new DiscoveryEvent(pongPeerMessage, nodeAddress)); @@ -365,23 +361,22 @@ private PongPeerMessage sendPong(InetSocketAddress nodeAddress, PingPeerMessage @VisibleForTesting FindNodePeerMessage sendFindNode(Node node) { - logger.debug("co.rsk.net.discovery.PeerExplorer.sendFindNode - Sending find node message:\n" + - "nodeAddress hostName: {}\n" + - "nodeAddress hostName: {}" - , node.getAddress().getHostName(), node.getAddress().getPort()); - InetSocketAddress nodeAddress = node.getAddress(); String id = UUID.randomUUID().toString(); FindNodePeerMessage findNodePeerMessage = FindNodePeerMessage.create(this.key.getNodeId(), id, this.key, this.networkId); - logger.debug("co.rsk.net.discovery.PeerExplorer.sendFindNode - findNodePeerMessage created: {}", findNodePeerMessage); + logger.debug("sendFindNode - Sending find node message to " + + "nodeAddress hostName: [{}], " + + "nodeAddress hostName: [{}], " + + "findNodePeerMessage: [{}]" + , node.getAddress().getHostName(), node.getAddress().getPort(), findNodePeerMessage); udpChannel.write(new DiscoveryEvent(findNodePeerMessage, nodeAddress)); PeerDiscoveryRequest request = PeerDiscoveryRequestBuilder.builder().messageId(id).relatedNode(node) .message(findNodePeerMessage).address(nodeAddress).expectedResponse(DiscoveryMessageType.NEIGHBORS) .expirationPeriod(requestTimeout).build(); - logger.debug("co.rsk.net.discovery.PeerExplorer.sendFindNode - request created: {}", request); + logger.debug("sendFindNode - request created: {}", request); pendingFindNodeRequests.put(findNodePeerMessage.getMessageId(), request); @@ -389,20 +384,18 @@ FindNodePeerMessage sendFindNode(Node node) { } private NeighborsPeerMessage sendNeighbors(InetSocketAddress nodeAddress, List nodes, String id) { - logger.debug("co.rsk.net.discovery.PeerExplorer.sendNeighbors - Sending neighbors message:\n" + - "nodeAddress hostName: {},\n" + - "nodeAddress port: {},\n" + - "id: {}\n" + - "nodes: {}" - , nodeAddress.getHostName(), nodeAddress.getPort(), id, nodes); - List nodesToSend = getRandomizeLimitedList(nodes, MAX_NODES_PER_MSG, 5); - logger.debug("co.rsk.net.discovery.PeerExplorer.sendNeighbors - nodesToSend: {}", nodesToSend); - NeighborsPeerMessage sendNodesMessage = NeighborsPeerMessage.create(nodesToSend, id, this.key, networkId); - logger.debug("co.rsk.net.discovery.PeerExplorer.sendNeighbors - sendNodesMessage created: {}", sendNodesMessage); + logger.debug("sendNeighbors - Sending neighbors message to " + + "nodeAddress hostName: [{}], " + + "nodeAddress port: [{}], " + + "id: [{}], " + + "nodes: [{}], " + + "nodesToSend: [{}], " + + "sendNodesMessage: [{}]" + , nodeAddress.getHostName(), nodeAddress.getPort(), id, nodes, nodesToSend, sendNodesMessage); udpChannel.write(new DiscoveryEvent(sendNodesMessage, nodeAddress)); @@ -420,8 +413,7 @@ private void purgeRequests() { } synchronized void clean() { - logger.trace("co.rsk.net.discovery.PeerExplorer.clean - Cleaning expired requests:\n" + - "state: {}", state); + logger.trace("clean - Cleaning expired requests with state: {}", state); if (state != ExecState.RUNNING) { logger.warn("Cannot clean as current state is {}", state); @@ -432,9 +424,6 @@ synchronized void clean() { } synchronized void update() { - logger.trace("co.rsk.net.discovery.PeerExplorer.update - Updating nodes list:\n" + - "state: {}", state); - if (state != ExecState.RUNNING) { logger.warn("Cannot update as current state is {}", state); return; @@ -442,44 +431,34 @@ synchronized void update() { List closestNodes = this.distanceTable.getClosestNodes(this.localNode.getId()); - logger.trace("co.rsk.net.discovery.PeerExplorer.update - closestNodes:\n" + - "closestNodes: {}", closestNodes); + logger.trace("update - Updating nodes list with state: {}, closestNodes: {}", state, closestNodes); this.askForMoreNodes(closestNodes); this.checkPeersPulse(closestNodes); } private void checkPeersPulse(List closestNodes) { - logger.trace("co.rsk.net.discovery.PeerExplorer.checkPeersPulse - Checking peers pulse for nodes:\n" + - "closestNodes: {}", closestNodes); - List nodesToCheck = this.getRandomizeLimitedList(closestNodes, MAX_NODES_TO_CHECK, 10); - logger.trace("co.rsk.net.discovery.PeerExplorer.checkPeersPulse - nodesToCheck: {}", nodesToCheck); + logger.trace("checkPeersPulse - Checking peers pulse for nodes: [{}], nodesToCheck: [{}]", closestNodes, nodesToCheck); nodesToCheck.forEach(node -> sendPing(node.getAddress(), 1, node)); } private void askForMoreNodes(List closestNodes) { - logger.trace("co.rsk.net.discovery.PeerExplorer.askForMoreNodes - Asking for more nodes:\n" + - "closestNodes: {}", closestNodes); - List nodesToAsk = getRandomizeLimitedList(closestNodes, MAX_NODES_TO_ASK, 5); - logger.trace("co.rsk.net.discovery.PeerExplorer.askForMoreNodes - nodesToAsk: {}", nodesToAsk); + logger.trace("askForMoreNodes - Asking for more nodes from closestNodes: [{}], nodesToAsk: [{}]", closestNodes, nodesToAsk); nodesToAsk.forEach(this::sendFindNode); } private List removeExpiredRequests(Map pendingRequests) { - logger.trace("co.rsk.net.discovery.PeerExplorer.removeExpiredRequests - Removing expired requests:\n" + - "pendingRequests: {}", pendingRequests); - List requests = pendingRequests.values().stream() .filter(PeerDiscoveryRequest::hasExpired).collect(Collectors.toList()); requests.forEach(r -> pendingRequests.remove(r.getMessageId())); - logger.trace("co.rsk.net.discovery.PeerExplorer.removeExpiredRequests - requests removed: {}", requests); + logger.trace("removeExpiredRequests - Removing expired requests from pendingRequests: [{}], requests: [{}]", pendingRequests, requests); return requests; } @@ -489,8 +468,7 @@ private void removeExpiredChallenges(List peerDiscoveryReq } private void resendExpiredPing(List peerDiscoveryRequests) { - logger.trace("co.rsk.net.discovery.PeerExplorer.resendExpiredPing - Resending expired pings:\n" + - "peerDiscoveryRequests: {}", peerDiscoveryRequests); + logger.trace("resendExpiredPing - Resending expired pings form peerDiscoveryRequests: [{}]", peerDiscoveryRequests); peerDiscoveryRequests.stream().filter(r -> r.getAttemptNumber() < RETRIES_COUNT) .forEach(r -> sendPing(r.getAddress(), r.getAttemptNumber() + 1, r.getRelatedNode())); @@ -507,10 +485,9 @@ private void removeConnections(List expiredRequests) { } private void removeConnection(Node node) { - logger.debug("co.rsk.net.discovery.PeerExplorer.removeConnection - Removing node:\n" + - "nodeId: {}\n" + - "nodeAddress hostName: {}\n" + - "nodeAddress port: {}", node.getHexId(), node.getAddress().getHostName(), node.getAddress().getPort()); + logger.debug("removeConnection - Removing node: [{}], " + + "nodeAddress hostName: [{}], " + + "nodeAddress port: [{}]", node.getHexId(), node.getAddress().getHostName(), node.getAddress().getPort()); this.establishedConnections.remove(node.getId()); this.distanceTable.removeNode(node); @@ -518,18 +495,16 @@ private void removeConnection(Node node) { } private void addConnection(PongPeerMessage message, String ip, int port) { - logger.debug("co.rsk.net.discovery.PeerExplorer.addConnection - Adding node:\n" + - "messageId: {}\n" + - "ip: {}\n" + - "port: {}\n" + - "allowMultipleConnectionsPerHostPort: {}", message.getMessageId(), ip, port, this.allowMultipleConnectionsPerHostPort); - Node senderNode = new Node(message.getNodeId().getID(), ip, port); boolean isLocalNode = StringUtils.equals(senderNode.getHexId(), this.localNode.getHexId()); - logger.debug("co.rsk.net.discovery.PeerExplorer.addConnection\n" + - "senderNode: {}\n" + - "isLocalNode: {}", senderNode, isLocalNode); + logger.debug("addConnection - Adding node with " + + "ip: [{}], " + + "port: [{}], " + + "messageId: [{}], " + + "allowMultipleConnectionsPerHostPort: [{}], " + + "senderNode: [{}], " + + "isLocalNode: [{}], ", ip, port, message.getMessageId(), this.allowMultipleConnectionsPerHostPort, senderNode, isLocalNode); if (isLocalNode) { return; @@ -541,7 +516,7 @@ private void addConnection(PongPeerMessage message, String ip, int port) { OperationResult result = this.distanceTable.addNode(senderNode); - logger.debug("co.rsk.net.discovery.PeerExplorer.addConnection - result: {}", result); + logger.debug("addConnection - result: [{}]", result); if (result.isSuccess()) { this.knownHosts.put(senderNode.getAddressAsString(), senderNode.getId()); diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java b/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java index 93f28ea0b00..d241d0d94a6 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java @@ -54,8 +54,7 @@ public synchronized OperationResult removeNode(Node node) { } public synchronized List getClosestNodes(NodeID nodeId) { - logger.debug("co.rsk.net.discovery.table.NodeDistanceTable.getClosestNodes - Getting closest nodes:\n" + - "nodeId: {}", nodeId.toString()); + logger.debug("getClosestNodes - Getting nodes closest to node: [{}]", nodeId.toString()); return getAllNodes().stream() .sorted(new NodeDistanceComparator(nodeId, this.distanceCalculator)) diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/table/OperationResult.java b/rskj-core/src/main/java/co/rsk/net/discovery/table/OperationResult.java index c797a17b41e..9f147d8d910 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/table/OperationResult.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/table/OperationResult.java @@ -45,7 +45,7 @@ public BucketEntry getAffectedEntry() { public String toString() { return new ToStringBuilder(this) .append("success", success) - .append("affectedEntry", affectedEntry.toString()) + .append("affectedEntry", affectedEntry) .toString(); } } From 644fbcc42e866cdbcaedc14364c0160b3cbf4d27 Mon Sep 17 00:00:00 2001 From: Reynold Morel Date: Mon, 30 Oct 2023 16:15:27 -0400 Subject: [PATCH 07/17] Fix codeQL alert --- rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java index 4019afbe048..e1f0a530137 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java @@ -295,9 +295,8 @@ synchronized PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt "nodeAddress hostName: [{}], " + "nodeAddress port: [{}], " + "attempt: [{}], " + - "node: [{}], " + "nodeMessage: [{}]" - , nodeAddress.getHostName(), nodeAddress.getPort(), attempt, node, nodeMessage); + , nodeAddress.getHostName(), nodeAddress.getPort(), attempt, nodeMessage); if (nodeMessage != null) { return nodeMessage; From 724bc4401bf1219c460137e0fdf9291e7871be46 Mon Sep 17 00:00:00 2001 From: Reynold Morel Date: Tue, 31 Oct 2023 13:44:06 -0400 Subject: [PATCH 08/17] Updating messages --- .../net/discovery/NodeChallengeManager.java | 3 +- .../co/rsk/net/discovery/PeerExplorer.java | 100 ++++++++---------- .../discovery/table/NodeDistanceTable.java | 2 - 3 files changed, 48 insertions(+), 57 deletions(-) diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java b/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java index 21ffd765d6f..fb17183adc1 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java @@ -36,7 +36,7 @@ public class NodeChallengeManager { private Map activeChallenges = new ConcurrentHashMap<>(); public NodeChallenge startChallenge(Node challengedNode, Node challenger, PeerExplorer explorer) { - logger.debug("startChallenge - Starting challenge for node: [{}] by challenger: [{}]", challengedNode.toString(), challenger.toString()); + logger.debug("startChallenge - Starting challenge for node: [{}] by challenger: [{}]", challengedNode, challenger); PingPeerMessage pingMessage = explorer.sendPing(challengedNode.getAddress(), 1, challengedNode); String messageId = pingMessage.getMessageId(); @@ -46,6 +46,7 @@ public NodeChallenge startChallenge(Node challengedNode, Node challenger, PeerEx } public NodeChallenge removeChallenge(String challengeId) { + logger.debug("removeChallenge - Removing challenge: [{}]", challengeId); return activeChallenges.remove(challengeId); } diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java index e1f0a530137..a5a6fae7f58 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java @@ -164,7 +164,7 @@ synchronized void handleMessage(DiscoveryEvent event) { "state: [{}], " + "type: [{}], " + "networkId: [{}]", - state, event.getMessage().getMessageType(), event.getMessage().getNetworkId().getAsInt()); + state, event.getMessage().getMessageType(), event.getMessage().getNetworkId()); if (state != ExecState.RUNNING) { logger.warn("Cannot handle message as current state is {}", state); @@ -176,8 +176,8 @@ synchronized void handleMessage(DiscoveryEvent event) { //have a networkId in the message yet, then just let them through, for now. if (event.getMessage().getNetworkId().isPresent() && event.getMessage().getNetworkId().getAsInt() != this.networkId) { - logger.debug("handleMessage - Message ignored because network id [{}] is different from [{}]", - event.getMessage().getNetworkId().getAsInt(), this.networkId); + logger.warn("handleMessage - Message ignored because remote peer's network id: [{}] is different from local network id: [{}]", + event.getMessage().getNetworkId(), this.networkId); return; } if (type == DiscoveryMessageType.PING) { @@ -202,8 +202,7 @@ private void handlePingMessage(InetSocketAddress address, PingPeerMessage messag Node connectedNode = this.establishedConnections.get(message.getNodeId()); logger.debug("handlePingMessage - Handling ping message with " + - "address hostName: [{}], " + - "address port: [{}], " + + "address: [{}/{}], " + "nodeId: [{}], " + "connectedNode: [{}]" , address.getHostName(), address.getPort(), message.getNodeId(), connectedNode); @@ -219,8 +218,7 @@ private void handlePong(InetSocketAddress pongAddress, PongPeerMessage message) PeerDiscoveryRequest request = this.pendingPingRequests.get(message.getMessageId()); logger.debug("handlePong - Handling pong message with " + - "pongAddress hostName: [{}], " + - "pongAddress port: [{}], " + + "address: [{}/{}], " + "messageId: [{}], " + "request: [{}]" , pongAddress.getHostName(), pongAddress.getPort(), message.getMessageId(), request); @@ -231,6 +229,8 @@ private void handlePong(InetSocketAddress pongAddress, PongPeerMessage message) if (challenge == null) { this.addConnection(message, request.getAddress().getHostString(), request.getAddress().getPort()); } + } else { + logger.warn("handlePong - Peer discovery request with id [{}] is either null or invalid", message.getMessageId()); } } @@ -238,36 +238,31 @@ private void handleFindNode(FindNodePeerMessage message) { NodeID nodeId = message.getNodeId(); Node connectedNode = this.establishedConnections.get(nodeId); - logger.debug("handleFindNode - Handling find node message with " + - "nodeId: {}, " + - "messageId: {}, " + - "connectedNode: {}" - , message.getNodeId(), message.getMessageId(), connectedNode); - if (connectedNode != null) { List nodesToSend = this.distanceTable.getClosestNodes(nodeId); - logger.debug("About to send [{}] neighbors to ip[{}] port[{}] nodeId[{}]", nodesToSend.size(), connectedNode.getHost(), connectedNode.getPort(), connectedNode.getHexId()); + logger.debug("handleFindNode - About to send [{}] neighbors to address[{}/{}], nodeId[{}] with messageId[{}]", + nodesToSend.size(), connectedNode.getHost(), connectedNode.getPort(), connectedNode.getHexId(), message.getMessageId()); this.sendNeighbors(connectedNode.getAddress(), nodesToSend, message.getMessageId()); updateEntry(connectedNode); + } else { + logger.warn("handleFindNode - Node with id [{}] is null", nodeId); } } private void handleNeighborsMessage(InetSocketAddress neighborsResponseAddress, NeighborsPeerMessage message) { - Node connectedNode = this.establishedConnections.get(message.getNodeId()); - - logger.debug("handleNeighborsMessage - Handling neighbors message with " + - "neighborsResponseAddress hostName: {}," + - "neighborsResponseAddress port: [{}]," + - "nodeId: [{}]," + - "messageId: [{}], " + - "nodesCount: [{}], " + - "nodes: [{}], " + - "connectedNode: [{}]" - , neighborsResponseAddress.getHostName(), neighborsResponseAddress.getPort(), message.getNodeId(), - message.getMessageId(), message.countNodes(), message.getNodes(), connectedNode); + NodeID nodeId = message.getNodeId(); + Node connectedNode = this.establishedConnections.get(nodeId); if (connectedNode != null) { - logger.debug("Neighbors received from [{}]", connectedNode.getHexId()); + logger.debug("handleNeighborsMessage - Neighbors received from id[{}], ip[{}], port[{}] with " + + "nodeId: [{}]," + + "messageId: [{}], " + + "nodesCount: [{}], " + + "nodes: [{}], " + + "connectedNode: [{}]", + connectedNode.getHexId(), neighborsResponseAddress.getHostName(), neighborsResponseAddress.getPort(), message.getNodeId(), + message.getMessageId(), message.countNodes(), message.getNodes(), connectedNode); + PeerDiscoveryRequest request = this.pendingFindNodeRequests.remove(message.getMessageId()); if (request != null && request.validateMessageResponse(neighborsResponseAddress, message)) { @@ -277,6 +272,8 @@ private void handleNeighborsMessage(InetSocketAddress neighborsResponseAddress, this.startConversationWithNewNodes(); } updateEntry(connectedNode); + } else { + logger.warn("handleFindNode - Node with id [{}] is null", nodeId); } } @@ -291,14 +288,9 @@ private PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt) { synchronized PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt, Node node) { PingPeerMessage nodeMessage = checkPendingPeerToAddress(nodeAddress); - logger.debug("sendPing - Sending ping message to " + - "nodeAddress hostName: [{}], " + - "nodeAddress port: [{}], " + - "attempt: [{}], " + - "nodeMessage: [{}]" - , nodeAddress.getHostName(), nodeAddress.getPort(), attempt, nodeMessage); - if (nodeMessage != null) { + logger.warn("sendPing - Node message to address [{}/{}] is null", nodeAddress.getHostName(), nodeAddress.getPort()); + return nodeMessage; } @@ -309,7 +301,11 @@ synchronized PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt localAddress.getPort(), id, this.key, this.networkId); - logger.debug("sendPing - nodeMessage created: [{}]", nodeMessage); + logger.debug("sendPing - Sending ping message to " + + "address: [{}/{}], " + + "attempt: [{}], " + + "nodeMessage: [{}]" + , nodeAddress.getHostName(), nodeAddress.getPort(), attempt, nodeMessage); udpChannel.write(new DiscoveryEvent(nodeMessage, nodeAddress)); @@ -347,8 +343,7 @@ private PongPeerMessage sendPong(InetSocketAddress nodeAddress, PingPeerMessage PongPeerMessage pongPeerMessage = PongPeerMessage.create(localAddress.getHostName(), localAddress.getPort(), message.getMessageId(), this.key, this.networkId); logger.debug("sendPong - Sending pong message to " + - "nodeAddress hostName: [{}], " + - "nodeAddress port: [{}], " + + "address: [{}/{}], " + "messageId: [{}], " + "pongPeerMessage: [{}]" , nodeAddress.getHostName(), nodeAddress.getPort(), message.getMessageId(), pongPeerMessage); @@ -364,18 +359,16 @@ FindNodePeerMessage sendFindNode(Node node) { String id = UUID.randomUUID().toString(); FindNodePeerMessage findNodePeerMessage = FindNodePeerMessage.create(this.key.getNodeId(), id, this.key, this.networkId); - logger.debug("sendFindNode - Sending find node message to " + - "nodeAddress hostName: [{}], " + - "nodeAddress hostName: [{}], " + - "findNodePeerMessage: [{}]" - , node.getAddress().getHostName(), node.getAddress().getPort(), findNodePeerMessage); - udpChannel.write(new DiscoveryEvent(findNodePeerMessage, nodeAddress)); PeerDiscoveryRequest request = PeerDiscoveryRequestBuilder.builder().messageId(id).relatedNode(node) .message(findNodePeerMessage).address(nodeAddress).expectedResponse(DiscoveryMessageType.NEIGHBORS) .expirationPeriod(requestTimeout).build(); - logger.debug("sendFindNode - request created: {}", request); + logger.debug("sendFindNode - Sending find node message to " + + "address: [{}/{}], " + + "findNodePeerMessage: [{}], " + + "request: [{}]" + , nodeAddress.getHostName(), nodeAddress.getPort(), findNodePeerMessage, request); pendingFindNodeRequests.put(findNodePeerMessage.getMessageId(), request); @@ -388,8 +381,7 @@ private NeighborsPeerMessage sendNeighbors(InetSocketAddress nodeAddress, List closestNodes = this.distanceTable.getClosestNodes(this.localNode.getId()); - logger.trace("update - Updating nodes list with state: {}, closestNodes: {}", state, closestNodes); + logger.trace("update - closestNodes: [{}]", closestNodes); this.askForMoreNodes(closestNodes); this.checkPeersPulse(closestNodes); @@ -484,9 +475,11 @@ private void removeConnections(List expiredRequests) { } private void removeConnection(Node node) { - logger.debug("removeConnection - Removing node: [{}], " + - "nodeAddress hostName: [{}], " + - "nodeAddress port: [{}]", node.getHexId(), node.getAddress().getHostName(), node.getAddress().getPort()); + if (logger.isDebugEnabled()) { + InetSocketAddress address = node.getAddress(); + logger.debug("removeConnection - Removing node: [{}], " + + "nodeAddress address: [{}/{}]", node.getHexId(), address.getHostName(), address.getPort()); + } this.establishedConnections.remove(node.getId()); this.distanceTable.removeNode(node); @@ -498,8 +491,7 @@ private void addConnection(PongPeerMessage message, String ip, int port) { boolean isLocalNode = StringUtils.equals(senderNode.getHexId(), this.localNode.getHexId()); logger.debug("addConnection - Adding node with " + - "ip: [{}], " + - "port: [{}], " + + "address: [{}/{}], " + "messageId: [{}], " + "allowMultipleConnectionsPerHostPort: [{}], " + "senderNode: [{}], " + diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java b/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java index d241d0d94a6..ea9f7f2283c 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java @@ -54,8 +54,6 @@ public synchronized OperationResult removeNode(Node node) { } public synchronized List getClosestNodes(NodeID nodeId) { - logger.debug("getClosestNodes - Getting nodes closest to node: [{}]", nodeId.toString()); - return getAllNodes().stream() .sorted(new NodeDistanceComparator(nodeId, this.distanceCalculator)) .collect(Collectors.toList()); From c23e97ef33ada8f0690c747319f1a710d02cbf32 Mon Sep 17 00:00:00 2001 From: Reynold Morel Date: Tue, 31 Oct 2023 14:27:20 -0400 Subject: [PATCH 09/17] Fix codeQL issues --- .../co/rsk/net/discovery/NodeChallengeManager.java | 10 +++++++--- .../main/java/co/rsk/net/discovery/PeerExplorer.java | 5 +++-- .../co/rsk/net/discovery/table/NodeDistanceTable.java | 3 --- 3 files changed, 10 insertions(+), 8 deletions(-) diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java b/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java index fb17183adc1..86ddcd400b2 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java @@ -36,7 +36,8 @@ public class NodeChallengeManager { private Map activeChallenges = new ConcurrentHashMap<>(); public NodeChallenge startChallenge(Node challengedNode, Node challenger, PeerExplorer explorer) { - logger.debug("startChallenge - Starting challenge for node: [{}] by challenger: [{}]", challengedNode, challenger); + logger.debug("startChallenge - Starting challenge for node: [{}] by challenger: [{}]", + challengedNode.getHexId(), challenger.getHexId()); PingPeerMessage pingMessage = explorer.sendPing(challengedNode.getAddress(), 1, challengedNode); String messageId = pingMessage.getMessageId(); @@ -46,8 +47,11 @@ public NodeChallenge startChallenge(Node challengedNode, Node challenger, PeerEx } public NodeChallenge removeChallenge(String challengeId) { - logger.debug("removeChallenge - Removing challenge: [{}]", challengeId); - return activeChallenges.remove(challengeId); + NodeChallenge removedChallenge = activeChallenges.remove(challengeId); + + logger.debug("removeChallenge - Removed challenge: [{}]", removedChallenge.getChallengeId()); + + return removedChallenge; } @VisibleForTesting diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java index a5a6fae7f58..f3e9541fe81 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java @@ -164,7 +164,8 @@ synchronized void handleMessage(DiscoveryEvent event) { "state: [{}], " + "type: [{}], " + "networkId: [{}]", - state, event.getMessage().getMessageType(), event.getMessage().getNetworkId()); + state, event.getMessage().getMessageType(), + event.getMessage().getNetworkId().isPresent() ? event.getMessage().getNetworkId().getAsInt() : null); if (state != ExecState.RUNNING) { logger.warn("Cannot handle message as current state is {}", state); @@ -177,7 +178,7 @@ synchronized void handleMessage(DiscoveryEvent event) { if (event.getMessage().getNetworkId().isPresent() && event.getMessage().getNetworkId().getAsInt() != this.networkId) { logger.warn("handleMessage - Message ignored because remote peer's network id: [{}] is different from local network id: [{}]", - event.getMessage().getNetworkId(), this.networkId); + event.getMessage().getNetworkId().getAsInt(), this.networkId); return; } if (type == DiscoveryMessageType.PING) { diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java b/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java index ea9f7f2283c..3e9397a36aa 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/table/NodeDistanceTable.java @@ -20,8 +20,6 @@ import co.rsk.net.NodeID; import org.ethereum.net.rlpx.Node; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; import java.util.*; import java.util.concurrent.ConcurrentHashMap; @@ -31,7 +29,6 @@ * Created by mario on 21/02/17. */ public class NodeDistanceTable { - private static final Logger logger = LoggerFactory.getLogger(NodeDistanceTable.class); private final Map buckets = new ConcurrentHashMap<>(); private final Node localNode; private final DistanceCalculator distanceCalculator; From 238737627f56c048ae4d559b663627acdb69ec81 Mon Sep 17 00:00:00 2001 From: Reynold Morel Date: Tue, 31 Oct 2023 14:36:39 -0400 Subject: [PATCH 10/17] Update removeChallenge log message --- .../main/java/co/rsk/net/discovery/NodeChallengeManager.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java b/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java index 86ddcd400b2..324aaf8bc77 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java @@ -49,7 +49,7 @@ public NodeChallenge startChallenge(Node challengedNode, Node challenger, PeerEx public NodeChallenge removeChallenge(String challengeId) { NodeChallenge removedChallenge = activeChallenges.remove(challengeId); - logger.debug("removeChallenge - Removed challenge: [{}]", removedChallenge.getChallengeId()); + logger.debug("removeChallenge - Removed challenge for node: [{}]", removedChallenge.getChallengedNode().getHexId()); return removedChallenge; } From e2a50ae598bf069ee9c2cbb248df605b8e3da496 Mon Sep 17 00:00:00 2001 From: Reynold Morel Date: Tue, 31 Oct 2023 15:29:31 -0400 Subject: [PATCH 11/17] Add toString to NodeChallenge --- .../main/java/co/rsk/net/discovery/NodeChallenge.java | 10 ++++++++++ .../co/rsk/net/discovery/NodeChallengeManager.java | 2 +- 2 files changed, 11 insertions(+), 1 deletion(-) diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallenge.java b/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallenge.java index 759a3c4c20c..6e0928f4774 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallenge.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallenge.java @@ -18,6 +18,7 @@ package co.rsk.net.discovery; +import org.apache.commons.lang3.builder.ToStringBuilder; import org.ethereum.net.rlpx.Node; /** @@ -45,4 +46,13 @@ public Node getChallenger() { public String getChallengeId() { return challengeId; } + + @Override + public String toString() { + return new ToStringBuilder(this) + .append("challengedNode", this.challengedNode) + .append("challenger", this.challenger) + .append("challengeId", this.challengeId) + .toString(); + } } diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java b/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java index 324aaf8bc77..5a759f7c9ca 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java @@ -49,7 +49,7 @@ public NodeChallenge startChallenge(Node challengedNode, Node challenger, PeerEx public NodeChallenge removeChallenge(String challengeId) { NodeChallenge removedChallenge = activeChallenges.remove(challengeId); - logger.debug("removeChallenge - Removed challenge for node: [{}]", removedChallenge.getChallengedNode().getHexId()); + logger.debug("removeChallenge - Removed challenge: [{}]", removedChallenge); return removedChallenge; } From 74453b6dc87eb4514fb0e44b385526a7a9cd799e Mon Sep 17 00:00:00 2001 From: Reynold Morel Date: Tue, 31 Oct 2023 15:45:23 -0400 Subject: [PATCH 12/17] Remove log from removeChallenge --- .../java/co/rsk/net/discovery/NodeChallengeManager.java | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java b/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java index 5a759f7c9ca..4400dfe4061 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/NodeChallengeManager.java @@ -47,11 +47,7 @@ public NodeChallenge startChallenge(Node challengedNode, Node challenger, PeerEx } public NodeChallenge removeChallenge(String challengeId) { - NodeChallenge removedChallenge = activeChallenges.remove(challengeId); - - logger.debug("removeChallenge - Removed challenge: [{}]", removedChallenge); - - return removedChallenge; + return activeChallenges.remove(challengeId); } @VisibleForTesting From 8489ead85f26429d1dab79a7809014c76cc4c38b Mon Sep 17 00:00:00 2001 From: Reynold Morel Date: Wed, 1 Nov 2023 14:11:42 -0400 Subject: [PATCH 13/17] Update some logs messages and variables --- .../main/java/co/rsk/net/discovery/PeerExplorer.java | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java index f3e9541fe81..9ed512b7708 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java @@ -165,7 +165,7 @@ synchronized void handleMessage(DiscoveryEvent event) { "type: [{}], " + "networkId: [{}]", state, event.getMessage().getMessageType(), - event.getMessage().getNetworkId().isPresent() ? event.getMessage().getNetworkId().getAsInt() : null); + event.getMessage().getNetworkId().isPresent()); if (state != ExecState.RUNNING) { logger.warn("Cannot handle message as current state is {}", state); @@ -178,7 +178,7 @@ synchronized void handleMessage(DiscoveryEvent event) { if (event.getMessage().getNetworkId().isPresent() && event.getMessage().getNetworkId().getAsInt() != this.networkId) { logger.warn("handleMessage - Message ignored because remote peer's network id: [{}] is different from local network id: [{}]", - event.getMessage().getNetworkId().getAsInt(), this.networkId); + event.getMessage().getNetworkId(), this.networkId); return; } if (type == DiscoveryMessageType.PING) { @@ -246,7 +246,7 @@ private void handleFindNode(FindNodePeerMessage message) { this.sendNeighbors(connectedNode.getAddress(), nodesToSend, message.getMessageId()); updateEntry(connectedNode); } else { - logger.warn("handleFindNode - Node with id [{}] is null", nodeId); + logger.warn("handleFindNode - Node with id: [{}] is not connected. Ignored", nodeId); } } @@ -274,7 +274,7 @@ private void handleNeighborsMessage(InetSocketAddress neighborsResponseAddress, } updateEntry(connectedNode); } else { - logger.warn("handleFindNode - Node with id [{}] is null", nodeId); + logger.warn("handleFindNode - Node with id: [{}] is not connected. Ignored", nodeId); } } @@ -290,7 +290,7 @@ synchronized PingPeerMessage sendPing(InetSocketAddress nodeAddress, int attempt PingPeerMessage nodeMessage = checkPendingPeerToAddress(nodeAddress); if (nodeMessage != null) { - logger.warn("sendPing - Node message to address [{}/{}] is null", nodeAddress.getHostName(), nodeAddress.getPort()); + logger.warn("sendPing - No ping message has been sent to address: [{}/{}], as there's pending one", nodeAddress.getHostName(), nodeAddress.getPort()); return nodeMessage; } From 2be7c2eb2072090d640fef38e5682f29546aa4b0 Mon Sep 17 00:00:00 2001 From: Reynold Morel Date: Thu, 2 Nov 2023 08:08:38 -0400 Subject: [PATCH 14/17] Remove isPresent call from log --- rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java index 9ed512b7708..30befdb4057 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java @@ -165,7 +165,7 @@ synchronized void handleMessage(DiscoveryEvent event) { "type: [{}], " + "networkId: [{}]", state, event.getMessage().getMessageType(), - event.getMessage().getNetworkId().isPresent()); + event.getMessage().getNetworkId()); if (state != ExecState.RUNNING) { logger.warn("Cannot handle message as current state is {}", state); From 1365f5b88e3d2ef594c0dce039d7289e6a3ec1c7 Mon Sep 17 00:00:00 2001 From: Reynold Morel Date: Fri, 3 Nov 2023 08:36:07 -0400 Subject: [PATCH 15/17] Update messages --- .../main/java/co/rsk/net/discovery/PeerExplorer.java | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java index 30befdb4057..90ba7abf922 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java @@ -161,10 +161,9 @@ void setUDPChannel(UDPChannel udpChannel) { synchronized void handleMessage(DiscoveryEvent event) { logger.debug("handleMessage - Handling message with " + - "state: [{}], " + - "type: [{}], " + - "networkId: [{}]", - state, event.getMessage().getMessageType(), + "type: [{}], " + + "networkId: [{}]", + event.getMessage().getMessageType(), event.getMessage().getNetworkId()); if (state != ExecState.RUNNING) { @@ -241,7 +240,7 @@ private void handleFindNode(FindNodePeerMessage message) { if (connectedNode != null) { List nodesToSend = this.distanceTable.getClosestNodes(nodeId); - logger.debug("handleFindNode - About to send [{}] neighbors to address[{}/{}], nodeId[{}] with messageId[{}]", + logger.debug("handleFindNode - About to send [{}] neighbors to address: [{}/{}], nodeId: [{}] with messageId: [{}]", nodesToSend.size(), connectedNode.getHost(), connectedNode.getPort(), connectedNode.getHexId(), message.getMessageId()); this.sendNeighbors(connectedNode.getAddress(), nodesToSend, message.getMessageId()); updateEntry(connectedNode); @@ -255,7 +254,7 @@ private void handleNeighborsMessage(InetSocketAddress neighborsResponseAddress, Node connectedNode = this.establishedConnections.get(nodeId); if (connectedNode != null) { - logger.debug("handleNeighborsMessage - Neighbors received from id[{}], ip[{}], port[{}] with " + + logger.debug("handleNeighborsMessage - Neighbors received from id: [{}], address: [{}/{}] with " + "nodeId: [{}]," + "messageId: [{}], " + "nodesCount: [{}], " + From fde468ef7ae8167c3556b9036a2a5351d56c4128 Mon Sep 17 00:00:00 2001 From: Reynold Morel Date: Thu, 7 Dec 2023 09:13:30 -0400 Subject: [PATCH 16/17] Code cleaning --- .../java/co/rsk/net/discovery/PeerExplorer.java | 14 +++++++++++--- 1 file changed, 11 insertions(+), 3 deletions(-) diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java index 90ba7abf922..965c04f5e82 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java @@ -19,7 +19,11 @@ package co.rsk.net.discovery; import co.rsk.net.NodeID; -import co.rsk.net.discovery.message.*; +import co.rsk.net.discovery.message.DiscoveryMessageType; +import co.rsk.net.discovery.message.FindNodePeerMessage; +import co.rsk.net.discovery.message.NeighborsPeerMessage; +import co.rsk.net.discovery.message.PingPeerMessage; +import co.rsk.net.discovery.message.PongPeerMessage; import co.rsk.net.discovery.table.NodeDistanceTable; import co.rsk.net.discovery.table.OperationResult; import co.rsk.net.discovery.table.PeerDiscoveryRequestBuilder; @@ -37,7 +41,12 @@ import java.net.InetSocketAddress; import java.net.UnknownHostException; import java.security.SecureRandom; -import java.util.*; +import java.util.ArrayList; +import java.util.HashSet; +import java.util.List; +import java.util.Map; +import java.util.Set; +import java.util.UUID; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.locks.Lock; import java.util.concurrent.locks.ReentrantLock; @@ -377,7 +386,6 @@ FindNodePeerMessage sendFindNode(Node node) { private NeighborsPeerMessage sendNeighbors(InetSocketAddress nodeAddress, List nodes, String id) { List nodesToSend = getRandomizeLimitedList(nodes, MAX_NODES_PER_MSG, 5); - NeighborsPeerMessage sendNodesMessage = NeighborsPeerMessage.create(nodesToSend, id, this.key, networkId); logger.debug("sendNeighbors - Sending neighbors message to " + From 8d7333ee45db216315c0062e35506448c4caf03b Mon Sep 17 00:00:00 2001 From: Reynold Morel Date: Thu, 7 Dec 2023 11:06:21 -0400 Subject: [PATCH 17/17] Code cleaning --- .../src/main/java/co/rsk/net/discovery/PeerExplorer.java | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java index 965c04f5e82..ce8ed79817c 100644 --- a/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java +++ b/rskj-core/src/main/java/co/rsk/net/discovery/PeerExplorer.java @@ -438,7 +438,8 @@ synchronized void update() { private void checkPeersPulse(List closestNodes) { List nodesToCheck = this.getRandomizeLimitedList(closestNodes, MAX_NODES_TO_CHECK, 10); - logger.trace("checkPeersPulse - Checking peers pulse for nodes: [{}], nodesToCheck: [{}]", closestNodes, nodesToCheck); + logger.trace("checkPeersPulse - Checking peers pulse for nodes: [{}], nodesToCheck: [{}]" + , closestNodes, nodesToCheck); nodesToCheck.forEach(node -> sendPing(node.getAddress(), 1, node)); } @@ -446,7 +447,8 @@ private void checkPeersPulse(List closestNodes) { private void askForMoreNodes(List closestNodes) { List nodesToAsk = getRandomizeLimitedList(closestNodes, MAX_NODES_TO_ASK, 5); - logger.trace("askForMoreNodes - Asking for more nodes from closestNodes: [{}], nodesToAsk: [{}]", closestNodes, nodesToAsk); + logger.trace("askForMoreNodes - Asking for more nodes from closestNodes: [{}], nodesToAsk: [{}]" + , closestNodes, nodesToAsk); nodesToAsk.forEach(this::sendFindNode); } @@ -456,7 +458,8 @@ private List removeExpiredRequests(Map pendingRequests.remove(r.getMessageId())); - logger.trace("removeExpiredRequests - Removing expired requests from pendingRequests: [{}], requests: [{}]", pendingRequests, requests); + logger.trace("removeExpiredRequests - Removing expired requests from pendingRequests: [{}], requests: [{}]" + , pendingRequests, requests); return requests; }