diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthProtocolManager.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthProtocolManager.java index 5b38a8db2a..01243e12fa 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthProtocolManager.java +++ b/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; } diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthServer.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthServer.java index 3bbb1b1388..d43b601563 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthServer.java +++ b/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 diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractPeerRequestTask.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractPeerRequestTask.java index 8fa5a734c9..bbe716a386 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractPeerRequestTask.java +++ b/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 extends AbstractPeerTask { + 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 extends AbstractPeerTask { 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()); } diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/BlockPropagationManager.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/BlockPropagationManager.java index 24ea2dfe41..b87097bfec 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/BlockPropagationManager.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/BlockPropagationManager.java @@ -175,6 +175,10 @@ public class BlockPropagationManager { 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 { .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); } } diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/ChainHeadTracker.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/ChainHeadTracker.java index b2b444f01d..25364146ea 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/ChainHeadTracker.java +++ b/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); } }); diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/fastsync/FastSyncTargetManager.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/fastsync/FastSyncTargetManager.java index 60dbbe63be..1762a01576 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/fastsync/FastSyncTargetManager.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/fastsync/FastSyncTargetManager.java @@ -91,6 +91,12 @@ class FastSyncTargetManager extends SyncTargetManager { .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.empty(); } else { diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/transactions/TransactionsMessageProcessor.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/transactions/TransactionsMessageProcessor.java index e9fd19b98b..0a514cc4aa 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/transactions/TransactionsMessageProcessor.java +++ b/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); } } diff --git a/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/network/DefaultP2PNetwork.java b/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/network/DefaultP2PNetwork.java index 92fffe8b20..dcd31b7e4f 100644 --- a/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/network/DefaultP2PNetwork.java +++ b/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; } diff --git a/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/RlpxAgent.java b/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/RlpxAgent.java index 693e02898e..1c0e6a9b26 100644 --- a/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/RlpxAgent.java +++ b/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 getActivePrioritizedConnections() { diff --git a/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/AbstractPeerConnection.java b/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/AbstractPeerConnection.java index 813e35ac8e..0d3084804b 100644 --- a/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/AbstractPeerConnection.java +++ b/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(", "))) diff --git a/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/ApiHandler.java b/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/ApiHandler.java index b61e011748..0fa4b9924a 100644 --- a/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/ApiHandler.java +++ b/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/ApiHandler.java @@ -82,15 +82,14 @@ final class ApiHandler extends SimpleChannelInboundHandler { 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: {}", - connection.getPeerInfo().getClientId()); + "Received Wire DISCONNECT with invalid RLP. Peer: {}", connection.getPeerInfo()); } 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); diff --git a/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/DeFramer.java b/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/DeFramer.java index db906eceb8..135cf44697 100644 --- a/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/DeFramer.java +++ b/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( - "Disconnecting from {} because no capabilities are shared.", peerInfo.getClientId()); + LOG.debug("Disconnecting because no capabilities are shared: {}", peerInfo); connectFuture.completeExceptionally( new IncompatiblePeerException("No shared capabilities")); connection.disconnect(DisconnectMessage.DisconnectReason.USELESS_PEER);