From de91d3122b218077e5df6c361c42f69d31a0a01c Mon Sep 17 00:00:00 2001 From: Stefan Pingel <16143240+pinges@users.noreply.github.com> Date: Fri, 22 Jul 2022 10:08:23 +1000 Subject: [PATCH] logging changes for peering (#4145) * logging changes for peering Signed-off-by: Stefan --- .../besu/ethereum/eth/manager/EthPeer.java | 33 ++++++++++--------- .../besu/ethereum/eth/manager/EthPeers.java | 11 ++----- .../eth/manager/EthProtocolManager.java | 6 ++-- .../connections/AbstractPeerConnection.java | 2 ++ .../p2p/rlpx/connections/netty/DeFramer.java | 2 +- 5 files changed, 27 insertions(+), 27 deletions(-) diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthPeer.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthPeer.java index 260aec318c..ff7c992d71 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthPeer.java +++ b/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 { } 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 { 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 { 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 { 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 { } 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 { @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 { @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()); diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthPeers.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthPeers.java index 442471aadf..c5074a2f90 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthPeers.java +++ b/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(); } 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 1bee6a0205..5edcb3236d 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 @@ -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); 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 96545c474f..e21e1800c6 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 @@ -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(); } } 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 11e8fc21d3..597784f913 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 @@ -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();