Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add logs peer discovery #2157

Merged
merged 17 commits into from
Dec 11, 2023
Merged

Add logs peer discovery #2157

merged 17 commits into from
Dec 11, 2023

Conversation

rmoreliovlabs
Copy link
Contributor

Description

Added more logs to PeerExplorer class in order to increase visibility during the peer discovery process.

Motivation and Context

How Has This Been Tested?

Types of changes

  • Bug fix (non-breaking change which fixes an issue)
  • New feature (non-breaking change which adds functionality)
  • Breaking change (fix or feature that would cause existing functionality to not work as expected)

Checklist:

  • My code follows the code style of this project.
  • My change requires a change to the documentation.
  • I have updated the documentation accordingly.
  • Tests for the changes have been added (for bug fixes / features)
  • Requires Activation Code (Hard Fork)
  • Other information:

@rmoreliovlabs
Copy link
Contributor Author

pipeline:run

@rmoreliovlabs rmoreliovlabs marked this pull request as ready for review October 25, 2023 14:21
casiojapi
casiojapi previously approved these changes Oct 26, 2023
Copy link
Contributor

@casiojapi casiojapi left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

private Map<String, NodeChallenge> 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" +
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
logger.debug("co.rsk.net.discovery.NodeChallengeManager.startChallenge - Starting challenge for node:\n" +
logger.debug("startChallenge - Starting challenge for node: [{}] by challenger: [{}]" +

I believe that a full path of a class is already included by a logger. This will simply duplicated it, won't it?

Also I'd use the technic used in other places, like "<something to log>: [{}]" and avoid new lines ("\n") as some tools might treat it as two separate logs (eg Grafana)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I see, I'll remove the path and use the format you mentioned for the variables in the logs message.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

private Map<String, NodeChallenge> 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());
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it's no need to call toString() on objects you want to log - it'll be done under the hood automatically. Plus null's would be handled correctly, plus the toString() method wouldn't be called at all for higher log levels

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done, I removed the toString() calls.

public String toString() {
return new ToStringBuilder(this)
.append("messageId", this.messageId)
.append("message", this.message.toString())
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wouldn't explicitly call toString() here and below - field could be null or in some cases its call might not be needed at all

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

Comment on lines 46 to 47
.append("message", this.message.toString())
.append("address", this.address.toString())
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wouldn't explicitly call toString() here and below

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

@@ -51,6 +54,9 @@ public synchronized OperationResult removeNode(Node node) {
}

public synchronized List<Node> getClosestNodes(NodeID nodeId) {
logger.debug("co.rsk.net.discovery.table.NodeDistanceTable.getClosestNodes - Getting closest nodes:\n" +
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

see similar comment above

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

@@ -160,6 +160,11 @@ void setUDPChannel(UDPChannel udpChannel) {
}

synchronized void handleMessage(DiscoveryEvent event) {
logger.debug("co.rsk.net.discovery.PeerExplorer.handleMessage - Handling message:\n" +
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

see similar comment above and also check similar log messages below

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

Comment on lines 258 to 255
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);

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

curious if it'd be possible to combine these two logs into one? And in similar cases below when multiple occurrences of 'logger.debug(..)` appear in one method? Simply just to not overwhelm our logs?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done, but I left some logs like this for some sendX() to indicate when a message gets created, like here.

private Map<String, NodeChallenge> 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());
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
logger.debug("startChallenge - Starting challenge for node: [{}] by challenger: [{}]", challengedNode.toString(), challenger.toString());
logger.debug("startChallenge - Starting challenge for node: [{}] by challenger: [{}]", challengedNode, challenger);

I'd also print a similar log in the removeChallenge() method down below with the result of removal

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Got it, will do.

@@ -350,17 +429,26 @@ synchronized void update() {
}

List<Node> closestNodes = this.distanceTable.getClosestNodes(this.localNode.getId());

logger.trace("update - Updating nodes list with state: {}, closestNodes: {}", state, closestNodes);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
logger.trace("update - Updating nodes list with state: {}, closestNodes: {}", state, closestNodes);
logger.trace("update - closestNodes: [{}]", closestNodes);

not sure we should long a state value here - it's gonna be always the same - RUNNING, wdyt?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You are right, the log inside the if block will log the state if it is different from RUNNING anyways.

@@ -51,6 +54,8 @@ public synchronized OperationResult removeNode(Node node) {
}

public synchronized List<Node> getClosestNodes(NodeID nodeId) {
logger.debug("getClosestNodes - Getting nodes closest to node: [{}]", nodeId.toString());
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

not sure we need to print a log here - it's a getter. It also seems that similar data is already printed upper the call stack

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'll remove it.

"state: [{}], " +
"type: [{}], " +
"networkId: [{}]",
state, event.getMessage().getMessageType(), event.getMessage().getNetworkId().getAsInt());
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
state, event.getMessage().getMessageType(), event.getMessage().getNetworkId().getAsInt());
state, event.getMessage().getMessageType(), event.getMessage().getNetworkId());

I'd rather not to call getAsInt(), as it looks like it can throw an exception in some circumstances, plus OptionalInt already implements toString() internally

@@ -170,6 +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 [{}]",
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
logger.debug("handleMessage - Message ignored because network id [{}] is different from [{}]",
logger.warn("handleMessage - Message ignored because remote peer's network id: [{}] is different from local network id: [{}]",

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

Comment on lines 366 to 372

logger.debug("sendFindNode - Sending find node message to " +
"nodeAddress hostName: [{}], " +
"nodeAddress hostName: [{}], " +
"findNodePeerMessage: [{}]"
, node.getAddress().getHostName(), node.getAddress().getPort(), findNodePeerMessage);

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

what about combining this with the one below?

@@ -335,6 +412,8 @@ private void purgeRequests() {
}

synchronized void clean() {
logger.trace("clean - Cleaning expired requests with state: {}", state);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we already print a WARN if state != ExecState.RUNNING, which should be rather a rare / exceptional case. I guess we could simply do logger.trace("clean - Cleaning obsolete requests ..."); just above this.purgeRequests();, wdyt?

"nodeAddress hostName: [{}], " +
"nodeAddress hostName: [{}], " +
"findNodePeerMessage: [{}]"
, node.getAddress().getHostName(), node.getAddress().getPort(), findNodePeerMessage);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
, node.getAddress().getHostName(), node.getAddress().getPort(), findNodePeerMessage);
, nodeAddress.getHostName(), nodeAddress.getPort(), findNodePeerMessage);

Comment on lines 368 to 369
"nodeAddress hostName: [{}], " +
"nodeAddress hostName: [{}], " +
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
"nodeAddress hostName: [{}], " +
"nodeAddress hostName: [{}], " +
"nodeAddress: [{}/{}], " +

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done, I also updated all instances where we log the addres to follow this format.

Comment on lines 487 to 483
logger.debug("removeConnection - Removing node: [{}], " +
"nodeAddress hostName: [{}], " +
"nodeAddress port: [{}]", node.getHexId(), node.getAddress().getHostName(), node.getAddress().getPort());

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
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 hostName: [{}], " +
"nodeAddress port: [{}]", node.getHexId(), address.getHostName(), address.getPort());
}

node.getAddress() seems to be quite heavy

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

@rmoreliovlabs
Copy link
Contributor Author

pipeline:run

"type: [{}], " +
"networkId: [{}]",
state, event.getMessage().getMessageType(),
event.getMessage().getNetworkId().isPresent() ? event.getMessage().getNetworkId().getAsInt() : null);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this might be error-prone. This doesn't handle the case when event.getMessage().getNetworkId() returns a null. Simply event.getMessage().getNetworkId()?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Using event.getMessage().getNetworkId() would trigger this alert in CodeQL. I could add another check, remove the network id from the message or dismiss the alert.

@@ -170,6 +177,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.warn("handleMessage - Message ignored because remote peer's network id: [{}] is different from local network id: [{}]",
event.getMessage().getNetworkId().getAsInt(), this.networkId);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this sequence of calls is error-prone. An exception can be thrown under some circumstances, eg when networkId is not set in a message. event.getMessage().getNetworkId()?

this.sendNeighbors(connectedNode.getAddress(), nodesToSend, message.getMessageId());
updateEntry(connectedNode);
} else {
logger.warn("handleFindNode - Node with id [{}] is null", nodeId);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
logger.warn("handleFindNode - Node with id [{}] is null", nodeId);
logger.warn("handleFindNode - Node with id: [{}] is not connected. Ignored", nodeId);

@@ -239,6 +273,8 @@ private void handleNeighborsMessage(InetSocketAddress neighborsResponseAddress,
this.startConversationWithNewNodes();
}
updateEntry(connectedNode);
} else {
logger.warn("handleFindNode - Node with id [{}] is null", nodeId);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
logger.warn("handleFindNode - Node with id [{}] is null", nodeId);
logger.warn("handleFindNode - Node with id: [{}] is not connected. Ignored", nodeId);

@@ -254,6 +290,8 @@ 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());
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
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());

"type: [{}], " +
"networkId: [{}]",
state, event.getMessage().getMessageType(),
event.getMessage().getNetworkId().isPresent());
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

seems there's a small typo here - .isPresent() can be omitted

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

Comment on lines 163 to 167
logger.debug("handleMessage - Handling message with " +
"state: [{}], " +
"type: [{}], " +
"networkId: [{}]",
state, event.getMessage().getMessageType(),
event.getMessage().getNetworkId());
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
logger.debug("handleMessage - Handling message with " +
"state: [{}], " +
"type: [{}], " +
"networkId: [{}]",
state, event.getMessage().getMessageType(),
event.getMessage().getNetworkId());
logger.debug("handleMessage - Handling message with " +
"type: [{}], " +
"networkId: [{}]",
event.getMessage().getMessageType(),
event.getMessage().getNetworkId());

@@ -219,17 +241,29 @@ private void handleFindNode(FindNodePeerMessage message) {

if (connectedNode != null) {
List<Node> 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[{}]",
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
logger.debug("handleFindNode - About to send [{}] neighbors to address[{}/{}], nodeId[{}] with messageId[{}]",
logger.debug("handleFindNode - About to send [{}] neighbors to address: [{}/{}], nodeId: [{}] with messageId: [{}]",


if (connectedNode != null) {
logger.debug("Neighbors received from [{}]", connectedNode.getHexId());
logger.debug("handleNeighborsMessage - Neighbors received from id[{}], ip[{}], port[{}] with " +
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
logger.debug("handleNeighborsMessage - Neighbors received from id[{}], ip[{}], port[{}] with " +
logger.debug("handleNeighborsMessage - Neighbors received from id: [{}], address: [{}/{}] with " +

Vovchyk
Vovchyk previously approved these changes Nov 20, 2023
@rmoreliovlabs rmoreliovlabs force-pushed the add-logs-peer-discovery branch from 1774290 to e23bd46 Compare November 29, 2023 15:34
@rmoreliovlabs
Copy link
Contributor Author

pipeline:run

1 similar comment
@nagarev
Copy link
Contributor

nagarev commented Nov 30, 2023

pipeline:run

@rmoreliovlabs rmoreliovlabs force-pushed the add-logs-peer-discovery branch from e23bd46 to 1365f5b Compare December 4, 2023 12:08
Copy link

sonarqubecloud bot commented Dec 7, 2023

Kudos, SonarCloud Quality Gate passed!    Quality Gate passed

Bug A 0 Bugs
Vulnerability A 0 Vulnerabilities
Security Hotspot A 0 Security Hotspots
Code Smell A 2 Code Smells

64.4% 64.4% Coverage
0.0% 0.0% Duplication

@Vovchyk
Copy link
Contributor

Vovchyk commented Dec 7, 2023

pipeline:run

3 similar comments
@Vovchyk
Copy link
Contributor

Vovchyk commented Dec 7, 2023

pipeline:run

@rmoreliovlabs
Copy link
Contributor Author

pipeline:run

@rmoreliovlabs
Copy link
Contributor Author

pipeline:run

@Vovchyk Vovchyk merged commit a8006f4 into master Dec 11, 2023
11 checks passed
@Vovchyk Vovchyk deleted the add-logs-peer-discovery branch December 11, 2023 12:16
@aeidelman aeidelman added this to the Fingerroot 5.4.0 milestone Jan 23, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants