[Minor] Add more logging around peer disconnects (#131)

Signed-off-by: Meredith Baxter <meredith.baxter@consensys.net>

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

@@ -211,6 +211,12 @@ public class EthProtocolManager implements ProtocolManager, MinedBlockObserver {
       return;
     } else if (!peer.statusHasBeenReceived()) {
       // Peers are required to send status messages before any other message type
+      LOG.debug(
+          "{} requires a Status ({}) message to be sent first.  Instead, received message {}.  Disconnecting from {}.",
+          this.getClass().getSimpleName(),
+          EthPV62.STATUS,
+          message.getData().getCode(),
+          peer);
       peer.disconnect(DisconnectReason.BREACH_OF_PROTOCOL);
       return;
     }
@@ -218,7 +224,7 @@ public class EthProtocolManager implements ProtocolManager, MinedBlockObserver {
     // Dispatch eth message
     final EthMessage ethMessage = new EthMessage(peer, message.getData());
     if (!peer.validateReceivedMessage(ethMessage)) {
-      LOG.warn("Unsolicited message received from {}, disconnecting", peer);
+      LOG.debug("Unsolicited message received from, disconnecting: {}", peer);
       peer.disconnect(DisconnectReason.BREACH_OF_PROTOCOL);
       return;
     }

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

@@ -84,6 +84,8 @@ class EthServer {
               ethereumWireProtocolConfiguration.getMaxGetBlockHeaders());
       message.getPeer().send(response);
     } catch (final RLPException e) {
+      LOG.debug(
+          "Received malformed GET_BLOCK_HEADERS message, disconnecting: {}", message.getPeer(), e);
       message.getPeer().disconnect(DisconnectReason.BREACH_OF_PROTOCOL);
     } catch (final PeerNotConnected peerNotConnected) {
       // Peer disconnected before we could respond - nothing to do
@@ -100,6 +102,8 @@ class EthServer {
               ethereumWireProtocolConfiguration.getMaxGetBlockBodies());
       message.getPeer().send(response);
     } catch (final RLPException e) {
+      LOG.debug(
+          "Received malformed GET_BLOCK_BODIES message, disconnecting: {}", message.getPeer(), e);
       message.getPeer().disconnect(DisconnectReason.BREACH_OF_PROTOCOL);
     } catch (final PeerNotConnected peerNotConnected) {
       // Peer disconnected before we could respond - nothing to do
@@ -114,6 +118,7 @@ class EthServer {
               blockchain, message.getData(), ethereumWireProtocolConfiguration.getMaxGetReceipts());
       message.getPeer().send(response);
     } catch (final RLPException e) {
+      LOG.debug("Received malformed GET_RECEIPTS message, disconnecting: {}", message.getPeer(), e);
       message.getPeer().disconnect(DisconnectReason.BREACH_OF_PROTOCOL);
     } catch (final PeerNotConnected peerNotConnected) {
       // Peer disconnected before we could respond - nothing to do
@@ -130,6 +135,8 @@ class EthServer {
               ethereumWireProtocolConfiguration.getMaxGetNodeData());
       message.getPeer().send(response);
     } catch (final RLPException e) {
+      LOG.debug(
+          "Received malformed GET_NODE_DATA message, disconnecting: {}", message.getPeer(), e);
       message.getPeer().disconnect(DisconnectReason.BREACH_OF_PROTOCOL);
     } catch (final PeerNotConnected peerNotConnected) {
       // Peer disconnected before we could respond - nothing to do

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

@@ -31,7 +31,11 @@ import java.util.Optional;
 import java.util.concurrent.CompletableFuture;
 import java.util.concurrent.TimeoutException;
 
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+
 public abstract class AbstractPeerRequestTask<R> extends AbstractPeerTask<R> {
+  private static final Logger LOG = LogManager.getLogger();
   private static final Duration DEFAULT_TIMEOUT = Duration.ofSeconds(5);
 
   private Duration timeout = DEFAULT_TIMEOUT;
@@ -100,6 +104,7 @@ public abstract class AbstractPeerRequestTask<R> extends AbstractPeerTask<R> {
       result.ifPresent(promise::complete);
     } catch (final RLPException e) {
       // Peer sent us malformed data - disconnect
+      LOG.debug("Disconnecting with BREACH_OF_PROTOCOL due to malformed message: {}", peer, e);
       peer.disconnect(DisconnectReason.BREACH_OF_PROTOCOL);
       promise.completeExceptionally(new PeerBreachedProtocolException());
     }

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/BlockPropagationManager.java

@@ -175,6 +175,10 @@ public class BlockPropagationManager<C> {
 
       importOrSavePendingBlock(block);
     } catch (final RLPException e) {
+      LOG.debug(
+          "Malformed NEW_BLOCK message received from peer, disconnecting: {}",
+          message.getPeer(),
+          e);
       message.getPeer().disconnect(DisconnectReason.BREACH_OF_PROTOCOL);
     }
   }
@@ -226,6 +230,10 @@ public class BlockPropagationManager<C> {
             .whenComplete((r, t) -> requestedBlocks.remove(newBlock.hash()));
       }
     } catch (final RLPException e) {
+      LOG.debug(
+          "Malformed NEW_BLOCK_HASHES message received from peer, disconnecting: {}",
+          message.getPeer(),
+          e);
       message.getPeer().disconnect(DisconnectReason.BREACH_OF_PROTOCOL);
     }
   }

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/ChainHeadTracker.java

@@ -83,7 +83,8 @@ public class ChainHeadTracker implements ConnectCallback {
                 peer.chainState().update(chainHeadHeader);
                 trailingPeerLimiter.enforceTrailingPeerLimit();
               } else {
-                LOG.debug("Failed to retrieve chain head information for " + peer, error);
+                LOG.debug(
+                    "Failed to retrieve chain head information.  Disconnecting {}. ", peer, error);
                 peer.disconnect(DisconnectReason.USELESS_PEER);
               }
             });

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/fastsync/FastSyncTargetManager.java

@@ -91,6 +91,12 @@ class FastSyncTargetManager<C> extends SyncTargetManager<C> {
         .thenApply(
             result -> {
               if (peerHasDifferentPivotBlock(result)) {
+                LOG.warn(
+                    "Best peer has wrong pivot block (#{}) expecting {} but received {}.  Disconnect: {}",
+                    pivotBlockHeader.getNumber(),
+                    pivotBlockHeader.getHash(),
+                    result.size() == 1 ? result.get(0).getHash() : "invalid response",
+                    bestPeer);
                 bestPeer.disconnect(DisconnectReason.USELESS_PEER);
                 return Optional.<EthPeer>empty();
               } else {

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/transactions/TransactionsMessageProcessor.java

@@ -82,6 +82,7 @@ class TransactionsMessageProcessor {
       transactionPool.addRemoteTransactions(transactions);
     } catch (final RLPException ex) {
       if (peer != null) {
+        LOG.debug("Malformed transaction message received, disconnecting: {}", peer, ex);
         peer.disconnect(DisconnectReason.BREACH_OF_PROTOCOL);
       }
     }

ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/network/DefaultP2PNetwork.java

@@ -255,6 +255,7 @@ public class DefaultP2PNetwork implements P2PNetwork {
   public boolean removeMaintainedConnectionPeer(final Peer peer) {
     final boolean wasRemoved = maintainedPeers.remove(peer);
     peerDiscoveryAgent.dropPeer(peer);
+    LOG.debug("Disconnect requested for peer {}.", peer);
     rlpxAgent.disconnect(peer.getId(), DisconnectReason.REQUESTED);
     return wasRemoved;
   }

ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/RlpxAgent.java

@@ -305,6 +305,9 @@ public class RlpxAgent {
         connection -> {
           if (!peerPermissions.allowOngoingConnection(
               connection.getPeer(), connection.initiatedRemotely())) {
+            LOG.debug(
+                "Disconnecting from peer that is not permitted to maintain ongoing connection: {}",
+                connection);
             connection.disconnect(DisconnectReason.REQUESTED);
           }
         });
@@ -332,21 +335,28 @@ public class RlpxAgent {
     final Peer peer = peerConnection.getPeer();
     // Deny connection if our local node isn't ready
     if (!localNode.isReady()) {
+      LOG.debug("Node is not ready. Disconnect incoming connection: {}", peerConnection);
       peerConnection.disconnect(DisconnectReason.UNKNOWN);
       return;
     }
     // Disconnect if too many peers
     if (!peerPrivileges.canExceedConnectionLimits(peer) && getConnectionCount() >= maxConnections) {
+      LOG.debug("Too many peers. Disconnect incoming connection: {}", peerConnection);
       peerConnection.disconnect(DisconnectReason.TOO_MANY_PEERS);
       return;
     }
     // Disconnect if too many remotely-initiated connections
     if (!peerPrivileges.canExceedConnectionLimits(peer) && remoteConnectionLimitReached()) {
+      LOG.debug(
+          "Too many remotely-initiated connections. Disconnect incoming connection: {}",
+          peerConnection);
       peerConnection.disconnect(DisconnectReason.TOO_MANY_PEERS);
       return;
     }
     // Disconnect if not permitted
     if (!peerPermissions.allowNewInboundConnectionFrom(peer)) {
+      LOG.debug(
+          "Node is not permitted to connect. Disconnect incoming connection: {}", peerConnection);
       peerConnection.disconnect(DisconnectReason.UNKNOWN);
       return;
     }
@@ -426,7 +436,13 @@ public class RlpxAgent {
         .filter(RlpxConnection::initiatedRemotely)
         .filter(conn -> !peerPrivileges.canExceedConnectionLimits(conn.getPeer()))
         .skip(maxRemotelyInitiatedConnections)
-        .forEach(c -> c.disconnect(DisconnectReason.TOO_MANY_PEERS));
+        .forEach(
+            conn -> {
+              LOG.debug(
+                  "Too many remotely initiated connections. Disconnect low-priority connection: {}",
+                  conn);
+              conn.disconnect(DisconnectReason.TOO_MANY_PEERS);
+            });
   }
 
   private void enforceConnectionLimits() {
@@ -438,7 +454,11 @@ public class RlpxAgent {
     getActivePrioritizedConnections()
         .skip(maxConnections)
         .filter(c -> !peerPrivileges.canExceedConnectionLimits(c.getPeer()))
-        .forEach(c -> c.disconnect(DisconnectReason.TOO_MANY_PEERS));
+        .forEach(
+            conn -> {
+              LOG.debug("Too many connections. Disconnect low-priority connection: {}", conn);
+              conn.disconnect(DisconnectReason.TOO_MANY_PEERS);
+            });
   }
 
   private Stream<RlpxConnection> getActivePrioritizedConnections() {

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

@@ -200,8 +200,8 @@ public abstract class AbstractPeerConnection implements PeerConnection {
   @Override
   public String toString() {
     return MoreObjects.toStringHelper(this)
-        .add("clientId", peerInfo.getClientId())
         .add("nodeId", peerInfo.getNodeId())
+        .add("clientId", peerInfo.getClientId())
         .add(
             "caps",
             agreedCapabilities.stream().map(Capability::toString).collect(Collectors.joining(", ")))

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

@@ -82,15 +82,14 @@ final class ApiHandler extends SimpleChannelInboundHandler<MessageData> {
             LOG.debug(
                 "Received Wire DISCONNECT ({}) from peer: {}",
                 reason.name(),
-                connection.getPeerInfo().getClientId());
+                connection.getPeerInfo());
           } catch (final RLPException e) {
             LOG.debug(
-                "Received Wire DISCONNECT with invalid RLP. Peer: {}",
+                "Received Wire DISCONNECT with invalid RLP. Peer: {}", connection.getPeerInfo());
-                connection.getPeerInfo().getClientId());
           } catch (final Exception e) {
             LOG.error(
                 "Received Wire DISCONNECT, but unable to parse reason. Peer: {}",
-                connection.getPeerInfo().getClientId(),
+                connection.getPeerInfo(),
                 e);
           }
           connection.terminateConnection(reason, true);

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

@@ -142,13 +142,13 @@ final class DeFramer extends ByteToMessageDecoder {
               String.format(
                   "Expected id %s, but got %s", expectedPeer.get().getId(), peerInfo.getNodeId());
           connectFuture.completeExceptionally(new UnexpectedPeerConnectionException(unexpectedMsg));
+          LOG.debug("{}. Disconnecting.", unexpectedMsg);
           connection.disconnect(DisconnectMessage.DisconnectReason.UNEXPECTED_ID);
         }
 
         // Check that we have shared caps
         if (capabilityMultiplexer.getAgreedCapabilities().size() == 0) {
-          LOG.debug(
+          LOG.debug("Disconnecting because no capabilities are shared: {}", peerInfo);
-              "Disconnecting from {} because no capabilities are shared.", peerInfo.getClientId());
           connectFuture.completeExceptionally(
               new IncompatiblePeerException("No shared capabilities"));
           connection.disconnect(DisconnectMessage.DisconnectReason.USELESS_PEER);