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 f7995a19bb1..65f9cea8dbe 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 @@ -257,14 +257,18 @@ 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.getShortNodeId()); + LOG.atDebug() + .setMessage("Protocol {} unavailable for this peer {}...") + .addArgument(protocolName) + .addArgument(this.getShortNodeId()) + .log(); return null; } if (permissioningProviders.stream() .anyMatch( p -> !p.isMessagePermitted(connectionToUse.getRemoteEnode(), messageData.getCode()))) { LOG.info( - "Permissioning blocked sending of message code {} to {}", + "Permissioning blocked sending of message code {} to {}...", messageData.getCode(), this.getShortNodeId()); if (LOG.isDebugEnabled()) { @@ -454,7 +458,7 @@ public PeerReputation getReputation() { } void handleDisconnect() { - LOG.debug("handleDisconnect - EthPeer {}", this); + LOG.trace("handleDisconnect - EthPeer {}", this); requestManagers.forEach( (protocolName, map) -> map.forEach((code, requestManager) -> requestManager.close())); 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 6a00fb90e76..8b14197b007 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 @@ -394,13 +394,14 @@ public void handleDisconnect( final DisconnectReason reason, final boolean initiatedByPeer) { if (ethPeers.registerDisconnect(connection)) { - LOG.debug( - "Disconnect - {} - {} - {}... - {} peers left\n{}", - initiatedByPeer ? "Inbound" : "Outbound", - reason, - connection.getPeer().getId().slice(0, 8), - ethPeers.peerCount(), - ethPeers); + LOG.atDebug() + .setMessage("Disconnect - {} - {} - {}... - {} peers left") + .addArgument(initiatedByPeer ? "Inbound" : "Outbound") + .addArgument(reason) + .addArgument(connection.getPeer().getId().slice(0, 8)) + .addArgument(ethPeers.peerCount()) + .log(); + LOG.trace("{}", ethPeers); } } @@ -410,7 +411,16 @@ private void handleStatusMessage(final EthPeer peer, final Message message) { peer.getConnection().getPeer().setForkId(forkId); try { if (!status.networkId().equals(networkId)) { - LOG.debug("Mismatched network id: {}, EthPeer {}", status.networkId(), peer); + LOG.atDebug() + .setMessage("Mismatched network id: {}, EthPeer {}...") + .addArgument(status.networkId()) + .addArgument(peer.getShortNodeId()) + .log(); + LOG.atTrace() + .setMessage("Mismatched network id: {}, EthPeer {}") + .addArgument(status.networkId()) + .addArgument(peer) + .log(); peer.disconnect(DisconnectReason.SUBPROTOCOL_TRIGGERED); } else if (!forkIdManager.peerCheck(forkId) && status.protocolVersion() > 63) { LOG.debug( @@ -428,7 +438,10 @@ private void handleStatusMessage(final EthPeer peer, final Message message) { peer.disconnect(DisconnectReason.SUBPROTOCOL_TRIGGERED); } else if (mergePeerFilter.isPresent() && mergePeerFilter.get().disconnectIfPoW(status, peer)) { - LOG.debug("Post-merge disconnect: peer still PoW {}", peer); + LOG.atDebug() + .setMessage("Post-merge disconnect: peer still PoW {}") + .addArgument(peer.getShortNodeId()) + .log(); handleDisconnect(peer.getConnection(), DisconnectReason.SUBPROTOCOL_TRIGGERED, false); } else { LOG.debug( diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractGetHeadersFromPeerTask.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractGetHeadersFromPeerTask.java index b7b2e76b5ce..9ec56d4c828 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractGetHeadersFromPeerTask.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractGetHeadersFromPeerTask.java @@ -125,18 +125,19 @@ protected Optional> processResponse( updatePeerChainState(peer, header); } - LOG.debug( - "Received {} of {} headers requested from peer {}", - headersList.size(), - count, - peer.getShortNodeId()); + LOG.atDebug() + .setMessage("Received {} of {} headers requested from peer {}...") + .addArgument(headersList.size()) + .addArgument(count) + .addArgument(peer.getShortNodeId()) + .log(); return Optional.of(headersList); } private void updatePeerChainState(final EthPeer peer, final BlockHeader blockHeader) { if (blockHeader.getNumber() > peer.chainState().getEstimatedHeight()) { LOG.atTrace() - .setMessage("Updating chain state for peer {} to block header {}") + .setMessage("Updating chain state for peer {}... to block header {}") .addArgument(peer::getShortNodeId) .addArgument(blockHeader::toLogString) .log(); diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetHeadersFromPeerByHashTask.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetHeadersFromPeerByHashTask.java index 8fb06b484e6..f3e931b4bae 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetHeadersFromPeerByHashTask.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetHeadersFromPeerByHashTask.java @@ -119,11 +119,12 @@ public static AbstractGetHeadersFromPeerTask forSingleHash( protected PendingPeerRequest sendRequest() { return sendRequestToPeer( peer -> { - LOG.debug( - "Requesting {} headers (hash {}...) from peer {}.", - count, - referenceHash.slice(0, 6), - peer.getShortNodeId()); + LOG.atDebug() + .setMessage("Requesting {} headers (hash {}...) from peer {}...") + .addArgument(count) + .addArgument(referenceHash.slice(0, 6)) + .addArgument(peer.getShortNodeId()) + .log(); return peer.getHeadersByHash(referenceHash, count, skip, reverse); }, minimumRequiredBlockNumber); diff --git a/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/discovery/internal/RecursivePeerRefreshState.java b/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/discovery/internal/RecursivePeerRefreshState.java index 70b1552e015..a392ee034de 100644 --- a/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/discovery/internal/RecursivePeerRefreshState.java +++ b/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/discovery/internal/RecursivePeerRefreshState.java @@ -74,8 +74,10 @@ public class RecursivePeerRefreshState { } void start(final List initialPeers, final Bytes target) { + // TODO check this flag earlier if (iterativeSearchInProgress) { - LOG.debug("Skip peer search because previous search is still in progress."); + LOG.debug( + "Skip peer search because previous search ({}) is still in progress.", currentRound); return; } LOG.debug("Start peer search."); @@ -93,7 +95,7 @@ private boolean reachedMaximumNumberOfRounds() { } private void addInitialPeers(final List initialPeers) { - LOG.debug("INITIAL PEERS: {}", initialPeers); + LOG.debug("{} INITIAL PEERS: {}", initialPeers.size(), initialPeers); this.initialPeers = initialPeers; for (final DiscoveryPeer peer : initialPeers) { final MetadataPeer iterationParticipant = 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 15978f4dfed..066f9122cbc 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 @@ -84,7 +84,11 @@ protected AbstractPeerConnection( this.inboundInitiated = inboundInitiated; this.initiatedAt = System.currentTimeMillis(); - LOG.debug("New PeerConnection ({}) established with peer {}", this, peer.getId()); + LOG.atDebug() + .setMessage("New PeerConnection ({}) established with peer {}...") + .addArgument(this) + .addArgument(peer.getId().slice(0, 16)) + .log(); } @Override @@ -164,7 +168,11 @@ public void terminateConnection(final DisconnectReason reason, final boolean pee // 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 {}", this, reason); + LOG.atTrace() + .setMessage("Terminating connection {}, reason {}") + .addArgument(this) + .addArgument(reason) + .log(); } protected abstract void closeConnectionImmediately(); @@ -176,11 +184,12 @@ public void disconnect(final DisconnectReason reason) { if (disconnected.compareAndSet(false, true)) { connectionEventDispatcher.dispatchDisconnect(this, reason, false); doSend(null, DisconnectMessage.create(reason)); - LOG.debug( - "Disconnecting connection {}, peer {}... reason {}", - System.identityHashCode(this), - peer.getId().slice(0, 16), - reason); + LOG.atDebug() + .setMessage("Disconnecting connection {}, peer {}... reason {}") + .addArgument(this.hashCode()) + .addArgument(peer.getId().slice(0, 16)) + .addArgument(reason) + .log(); closeConnection(); } }