[MINOR] Eth peer toString() improvements (#6174)

* modifications to log messages for simplification
* for debug logs, only use the short ID not the full peer
* log timeouts and useless counts

Signed-off-by: Sally MacFarlane <macfarla.github@gmail.com>

---------

Signed-off-by: Sally MacFarlane <macfarla.github@gmail.com>

Author: macfarla

ethereum/core/src/main/java/org/hyperledger/besu/ethereum/mainnet/headervalidationrules/TimestampBoundedByFutureParameter.java

@@ -23,7 +23,7 @@
 import org.slf4j.LoggerFactory;
 
 /**
- * Responsible for ensuring the timestamp of a block is not more than "acceptableClockDriftSeconds'
+ * Responsible for ensuring the timestamp of a block is not more than "acceptableClockDriftSeconds"
  * into the future.
  */
 public class TimestampBoundedByFutureParameter implements DetachedBlockHeaderValidationRule {

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthPeer.java

@@ -210,12 +210,16 @@ public void removeChainEstimatedHeightListener(final long listenerId) {
   }
 
   public void recordRequestTimeout(final int requestCode) {
-    LOG.debug("Timed out while waiting for response from peer {}", this);
+    LOG.debug("Timed out while waiting for response from peer {}", this.getShortNodeId());
+    LOG.trace("Timed out while waiting for response from peer {}", this);
     reputation.recordRequestTimeout(requestCode).ifPresent(this::disconnect);
   }
 
   public void recordUselessResponse(final String requestType) {
-    LOG.debug("Received useless response for request type {} from peer {}", requestType, this);
+    LOG.debug(
+        "Received useless response for request type {} from peer {}",
+        requestType,
+        this.getShortNodeId());
     reputation.recordUselessResponse(System.currentTimeMillis()).ifPresent(this::disconnect);
   }
 
@@ -253,14 +257,16 @@ public RequestManager.ResponseStream send(
       throws PeerNotConnected {
     if (connectionToUse.getAgreedCapabilities().stream()
         .noneMatch(capability -> capability.getName().equalsIgnoreCase(protocolName))) {
-      LOG.debug("Protocol {} unavailable for this peer {}", protocolName, this);
+      LOG.debug("Protocol {} unavailable for this peer {}", protocolName, this.getShortNodeId());
       return null;
     }
     if (permissioningProviders.stream()
         .anyMatch(
             p -> !p.isMessagePermitted(connectionToUse.getRemoteEnode(), messageData.getCode()))) {
       LOG.info(
-          "Permissioning blocked sending of message code {} to {}", messageData.getCode(), this);
+          "Permissioning blocked sending of message code {} to {}",
+          messageData.getCode(),
+          this.getShortNodeId());
       if (LOG.isDebugEnabled()) {
         LOG.debug(
             "Permissioning blocked by providers {}",
@@ -593,8 +599,8 @@ public boolean hasSupportForMessage(final int messageCode) {
   @Override
   public String toString() {
     return String.format(
-        "PeerId %s, reputation %s, validated? %s, disconnected? %s, client: %s, connection %s, enode %s",
-        nodeId(),
+        "PeerId: %s... %s, validated? %s, disconnected? %s, client: %s, %s, %s",
+        getShortNodeId(),
         reputation,
         isFullyValidated(),
         isDisconnected(),

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthPeers.java

@@ -197,7 +197,8 @@ private boolean registerDisconnect(
         disconnectCallbacks.forEach(callback -> callback.onDisconnect(peer));
         peer.handleDisconnect();
         abortPendingRequestsAssignedToDisconnectedPeers();
-        LOG.debug("Disconnected EthPeer {}", peer);
+        LOG.debug("Disconnected EthPeer {}", peer.getShortNodeId());
+        LOG.trace("Disconnected EthPeer {}", peer);
       }
     }
     reattemptPendingPeerRequests();
@@ -391,7 +392,7 @@ public void disconnectWorstUselessPeer() {
               LOG.atDebug()
                   .setMessage(
                       "disconnecting peer {}. Waiting for better peers. Current {} of max {}")
-                  .addArgument(peer)
+                  .addArgument(peer::getShortNodeId)
                   .addArgument(this::peerCount)
                   .addArgument(this::getMaxPeers)
                   .log();

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthProtocolManager.java

@@ -382,11 +382,9 @@ public boolean shouldConnect(final Peer peer, final boolean incoming) {
     if (peer.getForkId().map(forkId -> forkIdManager.peerCheck(forkId)).orElse(true)) {
       LOG.trace("ForkId OK or not available");
       if (ethPeers.shouldConnect(peer, incoming)) {
-        LOG.trace("EthPeers should connect is TRUE");
         return true;
       }
     }
-    LOG.trace("Should connect in EthProtocolManager returns false");
     return false;
   }
 
@@ -397,10 +395,10 @@ public void handleDisconnect(
       final boolean initiatedByPeer) {
     if (ethPeers.registerDisconnect(connection)) {
       LOG.debug(
-          "Disconnect - {} - {} - {} - {} peers left\n{}",
+          "Disconnect - {} - {} - {}... - {} peers left\n{}",
           initiatedByPeer ? "Inbound" : "Outbound",
           reason,
-          connection.getPeer().getId(),
+          connection.getPeer().getId().slice(0, 16),
           ethPeers.peerCount(),
           ethPeers);
     }

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/PeerReputation.java

@@ -65,7 +65,10 @@ public PeerReputation(final int initialScore, final int maxScore) {
   public Optional<DisconnectReason> recordRequestTimeout(final int requestCode) {
     final int newTimeoutCount = getOrCreateTimeoutCount(requestCode).incrementAndGet();
     if (newTimeoutCount >= TIMEOUT_THRESHOLD) {
-      LOG.debug("Disconnection triggered by repeated timeouts");
+      LOG.debug(
+          "Disconnection triggered by {} repeated timeouts for requestCode {}",
+          newTimeoutCount,
+          requestCode);
       score -= LARGE_ADJUSTMENT;
       return Optional.of(DisconnectReason.TIMEOUT);
     } else {
@@ -113,7 +116,9 @@ private boolean shouldRemove(final Long timestamp, final long currentTimestamp)
 
   @Override
   public String toString() {
-    return String.format("PeerReputation " + score);
+    return String.format(
+        "PeerReputation score: %d, timeouts: %s, useless: %s",
+        score, timeoutCounts(), uselessResponseTimes.size());
   }
 
   @Override

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractGetHeadersFromPeerTask.java

@@ -64,7 +64,7 @@ protected AbstractGetHeadersFromPeerTask(
   protected Optional<List<BlockHeader>> processResponse(
       final boolean streamClosed, final MessageData message, final EthPeer peer) {
     if (streamClosed) {
-      // All outstanding requests have been responded to and we still haven't found the response
+      // All outstanding requests have been responded to, and we still haven't found the response
       // we wanted. It must have been empty or contain data that didn't match.
       peer.recordUselessResponse("headers");
       return Optional.of(Collections.emptyList());
@@ -74,19 +74,19 @@ protected Optional<List<BlockHeader>> processResponse(
     final List<BlockHeader> headers = headersMessage.getHeaders(protocolSchedule);
     if (headers.isEmpty()) {
       // Message contains no data - nothing to do
-      LOG.debug("headers.isEmpty. Peer: {}", peer);
+      LOG.debug("headers.isEmpty. Peer: {}", peer.getShortNodeId());
       return Optional.empty();
     }
     if (headers.size() > count) {
       // Too many headers - this isn't our response
-      LOG.debug("headers.size()>count. Peer: {}", peer);
+      LOG.debug("headers.size()>count. Peer: {}", peer.getShortNodeId());
       return Optional.empty();
     }
 
     final BlockHeader firstHeader = headers.get(0);
     if (!matchesFirstHeader(firstHeader)) {
       // This isn't our message - nothing to do
-      LOG.debug("!matchesFirstHeader. Peer: {}", peer);
+      LOG.debug("!matchesFirstHeader. Peer: {}", peer.getShortNodeId());
       return Optional.empty();
     }
 
@@ -100,7 +100,7 @@ protected Optional<List<BlockHeader>> processResponse(
       header = headers.get(i);
       if (header.getNumber() != prevBlockHeader.getNumber() + expectedDelta) {
         // Skip doesn't match, this isn't our data
-        LOG.debug("header not matching the expected number. Peer: {}", peer);
+        LOG.debug("header not matching the expected number. Peer: {}", peer.getShortNodeId());
         return Optional.empty();
       }
       // if headers are supposed to be sequential check if a chain is formed
@@ -110,7 +110,7 @@ protected Optional<List<BlockHeader>> processResponse(
         if (!parent.getHash().equals(child.getParentHash())) {
           LOG.debug(
               "Sequential headers must form a chain through hashes (BREACH_OF_PROTOCOL), disconnecting peer: {}",
-              peer);
+              peer.getShortNodeId());
           peer.disconnect(DisconnectMessage.DisconnectReason.BREACH_OF_PROTOCOL);
           return Optional.empty();
         }
@@ -125,7 +125,11 @@ protected Optional<List<BlockHeader>> processResponse(
       updatePeerChainState(peer, header);
     }
 
-    LOG.debug("Received {} of {} headers requested from peer {}", headersList.size(), count, peer);
+    LOG.debug(
+        "Received {} of {} headers requested from peer {}",
+        headersList.size(),
+        count,
+        peer.getShortNodeId());
     return Optional.of(headersList);
   }
 

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractPeerRequestTask.java

@@ -108,8 +108,11 @@ private void handleMessage(
           });
     } catch (final RLPException e) {
       // Peer sent us malformed data - disconnect
-      LOG.debug("Disconnecting with BREACH_OF_PROTOCOL due to malformed message: {}", peer, e);
-      LOG.trace("Message data: {}", message.getData());
+      LOG.debug(
+          "Disconnecting with BREACH_OF_PROTOCOL due to malformed message: {}",
+          peer.getShortNodeId(),
+          e);
+      LOG.trace("Peer {} Malformed message data: {}", peer, message.getData());
       peer.disconnect(DisconnectReason.BREACH_OF_PROTOCOL);
       promise.completeExceptionally(new PeerBreachedProtocolException());
     }

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractRetryingSwitchingPeerTask.java

@@ -146,7 +146,7 @@ private void refreshPeers() {
                 LOG.atDebug()
                     .setMessage(
                         "Refresh peers disconnecting peer {}. Waiting for better peers. Current {} of max {}")
-                    .addArgument(peer)
+                    .addArgument(peer::getShortNodeId)
                     .addArgument(peers::peerCount)
                     .addArgument(peers::getMaxPeers)
                     .log();

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetHeadersFromPeerByHashTask.java

@@ -123,7 +123,7 @@ protected PendingPeerRequest sendRequest() {
               "Requesting {} headers (hash {}...) from peer {}.",
               count,
               referenceHash.slice(0, 6),
-              peer);
+              peer.getShortNodeId());
           return peer.getHeadersByHash(referenceHash, count, skip, reverse);
         },
         minimumRequiredBlockNumber);

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetHeadersFromPeerByNumberTask.java

@@ -78,7 +78,10 @@ protected PendingPeerRequest sendRequest() {
     return sendRequestToPeer(
         peer -> {
           LOG.debug(
-              "Requesting {} headers (blockNumber {}) from peer {}.", count, blockNumber, peer);
+              "Requesting {} headers (blockNumber {}) from peer {}.",
+              count,
+              blockNumber,
+              peer.getShortNodeId());
           return peer.getHeadersByNumber(blockNumber, count, skip, reverse);
         },
         blockNumber);