logging changes for peering (#4145)

* logging changes for peering

Signed-off-by: Stefan <stefan.pingel@consensys.net>

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

@@ -15,7 +15,6 @@
 package org.hyperledger.besu.ethereum.eth.manager;
 
 import static com.google.common.base.Preconditions.checkArgument;
-import static org.hyperledger.besu.util.Slf4jLambdaHelper.traceLambda;
 
 import org.hyperledger.besu.datatypes.Hash;
 import org.hyperledger.besu.ethereum.core.BlockHeader;
@@ -211,7 +210,7 @@ public class EthPeer implements Comparable<EthPeer> {
   }
 
   public void recordUselessResponse(final String requestType) {
-    LOG.debug("Received useless response for {} from peer {}", requestType, this);
+    LOG.debug("Received useless response for request type {} from peer {}", requestType, this);
     reputation.recordUselessResponse(System.currentTimeMillis()).ifPresent(this::disconnect);
   }
 
@@ -231,15 +230,13 @@ public class EthPeer implements Comparable<EthPeer> {
       final MessageData messageData, final String protocolName) throws PeerNotConnected {
     if (connection.getAgreedCapabilities().stream()
         .noneMatch(capability -> capability.getName().equalsIgnoreCase(protocolName))) {
-      LOG.debug("Protocol {} unavailable for this peer ", protocolName);
+      LOG.debug("Protocol {} unavailable for this peer {}", protocolName, this);
       return null;
     }
     if (permissioningProviders.stream()
         .anyMatch(p -> !p.isMessagePermitted(connection.getRemoteEnode(), messageData.getCode()))) {
       LOG.info(
-          "Permissioning blocked sending of message code {} to {}",
-          messageData.getCode(),
-          connection.getRemoteEnode());
+          "Permissioning blocked sending of message code {} to {}", messageData.getCode(), this);
       if (LOG.isDebugEnabled()) {
         LOG.debug(
             "Permissioning blocked by providers {}",
@@ -256,7 +253,7 @@ public class EthPeer implements Comparable<EthPeer> {
       LOG.error(
           "Sending {} message to peer ({}) which exceeds local message size limit of {} bytes.  Message code: {}, Message Size: {}",
           protocolName,
-          connection.getRemoteEnode(),
+          this,
           maxMessageSize,
           messageData.getCode(),
           messageData.getSize());
@@ -389,9 +386,10 @@ public class EthPeer implements Comparable<EthPeer> {
             requestManager -> requestManager.dispatchResponse(ethMessage),
             () -> {
               LOG.trace(
-                  "Message {} not expected has just been received for {} ",
+                  "Message {} not expected has just been received for protocol {}, peer {} ",
                   messageCode,
-                  protocolName);
+                  protocolName,
+                  this);
             });
   }
 
@@ -424,8 +422,7 @@ public class EthPeer implements Comparable<EthPeer> {
   }
 
   void handleDisconnect() {
-    traceLambda(
-        LOG, "handleDisconnect - peer... {}, {}", this::getShortNodeId, this::getReputation);
+    LOG.debug("handleDisconnect - EthPeer {}", this);
 
     requestManagers.forEach(
         (protocolName, map) -> map.forEach((code, requestManager) -> requestManager.close()));
@@ -554,8 +551,14 @@ public class EthPeer implements Comparable<EthPeer> {
   @Override
   public String toString() {
     return String.format(
-        "Peer %s... %s, validated? %s, disconnected? %s",
-        getShortNodeId(), reputation, isFullyValidated(), isDisconnected());
+        "PeerId %s, reputation %s, validated? %s, disconnected? %s, client: %s, connection %s, enode %s",
+        nodeId(),
+        reputation,
+        isFullyValidated(),
+        isDisconnected(),
+        connection.getPeerInfo().getClientId(),
+        System.identityHashCode(connection),
+        connection.getPeer().getEnodeURLString());
   }
 
   @Nonnull
@@ -565,10 +568,10 @@ public class EthPeer implements Comparable<EthPeer> {
 
   @Override
   public int compareTo(final @Nonnull EthPeer ethPeer) {
-    int repCompare = this.reputation.compareTo(ethPeer.reputation);
+    final int repCompare = this.reputation.compareTo(ethPeer.reputation);
     if (repCompare != 0) return repCompare;
 
-    int headStateCompare =
+    final int headStateCompare =
         Long.compare(
             this.chainHeadState.getBestBlock().getNumber(),
             ethPeer.chainHeadState.getBestBlock().getNumber());

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

@@ -17,7 +17,6 @@ package org.hyperledger.besu.ethereum.eth.manager;
 import org.hyperledger.besu.ethereum.eth.manager.EthPeer.DisconnectCallback;
 import org.hyperledger.besu.ethereum.eth.peervalidation.PeerValidator;
 import org.hyperledger.besu.ethereum.p2p.rlpx.connections.PeerConnection;
-import org.hyperledger.besu.ethereum.p2p.rlpx.wire.PeerInfo;
 import org.hyperledger.besu.metrics.BesuMetricCategory;
 import org.hyperledger.besu.plugin.services.MetricsSystem;
 import org.hyperledger.besu.plugin.services.permissioning.NodeMessagePermissioningProvider;
@@ -107,7 +106,8 @@ public class EthPeers {
             maxMessageSize,
             clock,
             permissioningProviders);
-    connections.putIfAbsent(peerConnection, peer);
+    final EthPeer ethPeer = connections.putIfAbsent(peerConnection, peer);
+    LOG.debug("Adding new EthPeer {}", ethPeer);
   }
 
   public void registerDisconnect(final PeerConnection connection) {
@@ -116,12 +116,7 @@ public class EthPeers {
       disconnectCallbacks.forEach(callback -> callback.onDisconnect(peer));
       peer.handleDisconnect();
       abortPendingRequestsAssignedToDisconnectedPeers();
-      final PeerInfo peerInfo = peer.getConnection().getPeerInfo();
-      LOG.debug(
-          "Disconnected EthPeer {}, client ID: {}, {}",
-          peerInfo.getNodeId(),
-          peerInfo.getClientId(),
-          peer.getReputation());
+      LOG.debug("Disconnected EthPeer {}", peer);
     }
     reattemptPendingPeerRequests();
   }

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

@@ -273,7 +273,7 @@ public class EthProtocolManager implements ProtocolManager, MinedBlockObserver {
     final EthMessage ethMessage = new EthMessage(ethPeer, messageData);
 
     if (!ethPeer.validateReceivedMessage(ethMessage, getSupportedProtocol())) {
-      LOG.debug("Unsolicited message received from, disconnecting: {}", ethPeer);
+      LOG.debug("Unsolicited message received, disconnecting from EthPeer: {}", ethPeer);
       ethPeer.disconnect(DisconnectReason.BREACH_OF_PROTOCOL);
       return;
     }
@@ -360,7 +360,7 @@ public class EthProtocolManager implements ProtocolManager, MinedBlockObserver {
     final StatusMessage status = StatusMessage.readFrom(data);
     try {
       if (!status.networkId().equals(networkId)) {
-        LOG.debug("{} has mismatched network id: {}", peer, status.networkId());
+        LOG.debug("Mismatched network id: {}, EthPeer {}", status.networkId(), peer);
         peer.disconnect(DisconnectReason.SUBPROTOCOL_TRIGGERED);
       } else if (!forkIdManager.peerCheck(status.forkId()) && status.protocolVersion() > 63) {
         LOG.debug(
@@ -387,7 +387,7 @@ public class EthProtocolManager implements ProtocolManager, MinedBlockObserver {
             status.bestHash(), status.totalDifficulty(), status.protocolVersion());
       }
     } catch (final RLPException e) {
-      LOG.debug("Unable to parse status message.", e);
+      LOG.debug("Unable to parse status message from peer {}.", peer, e);
       // Parsing errors can happen when clients broadcast network ids outside the int range,
       // So just disconnect with "subprotocol" error rather than "breach of protocol".
       peer.disconnect(DisconnectReason.SUBPROTOCOL_TRIGGERED);

ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/AbstractPeerConnection.java

@@ -147,6 +147,7 @@ public abstract class AbstractPeerConnection implements PeerConnection {
     // Always ensure the context gets closed immediately even if we previously sent a disconnect
     // message and are waiting to close.
     closeConnectionImmediately();
+    LOG.debug("Terminating connection {}, reason {}", System.identityHashCode(this), reason);
   }
 
   protected abstract void closeConnectionImmediately();
@@ -158,6 +159,7 @@ public abstract class AbstractPeerConnection implements PeerConnection {
     if (disconnected.compareAndSet(false, true)) {
       connectionEventDispatcher.dispatchDisconnect(this, reason, false);
       doSend(null, DisconnectMessage.create(reason));
+      LOG.debug("Disconnecting connection {}, reason {}", System.identityHashCode(this), reason);
       closeConnection();
     }
   }

ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/DeFramer.java

@@ -241,7 +241,7 @@ final class DeFramer extends ByteToMessageDecoder {
     if (connectFuture.isDone() && !connectFuture.isCompletedExceptionally()) {
       connectFuture
           .get()
-          .terminateConnection(DisconnectMessage.DisconnectReason.TCP_SUBSYSTEM_ERROR, true);
+          .terminateConnection(DisconnectMessage.DisconnectReason.TCP_SUBSYSTEM_ERROR, false);
     } else {
       connectFuture.completeExceptionally(throwable);
       ctx.close();