From c9fbc9d3fd828985c6bf3ef3d266716740134515 Mon Sep 17 00:00:00 2001 From: Adrian Sutton Date: Thu, 25 Oct 2018 06:00:59 +1000 Subject: [PATCH] [NC-1675] Apply more appropriate log levels (#133) Reduce log level for a number of common situations to DEBUG and general tidy-up of output. --- .../eth/manager/AbstractRetryingPeerTask.java | 2 +- .../eth/manager/EthProtocolManager.java | 7 ++++--- .../ethereum/eth/manager/PeerReputation.java | 4 ++-- .../ethereum/eth/sync/Downloader.java | 14 +++++++++++--- .../tasks/DetermineCommonAncestorTask.java | 9 ++++++++- .../tasks/GetHeadersFromPeerByNumberTask.java | 2 +- .../PipelinedImportChainSegmentTask.java | 5 +++-- .../p2p/netty/AbstractHandshakeHandler.java | 2 +- .../ethereum/p2p/netty/ApiHandler.java | 6 ++---- .../pantheon/ethereum/p2p/netty/DeFramer.java | 19 +++++++++++++++++-- .../ethereum/p2p/wire/Capability.java | 9 --------- 11 files changed, 50 insertions(+), 29 deletions(-) diff --git a/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/manager/AbstractRetryingPeerTask.java b/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/manager/AbstractRetryingPeerTask.java index 396ac0e0cf..8a7fb313a9 100644 --- a/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/manager/AbstractRetryingPeerTask.java +++ b/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/manager/AbstractRetryingPeerTask.java @@ -84,7 +84,7 @@ public abstract class AbstractRetryingPeerTask extends AbstractEthTask { return; } - LOG.info( + LOG.debug( "Retrying after recoverable failure from peer task {}: {}", this.getClass().getSimpleName(), cause.getMessage()); diff --git a/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/manager/EthProtocolManager.java b/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/manager/EthProtocolManager.java index cc65812413..3509527039 100644 --- a/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/manager/EthProtocolManager.java +++ b/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/manager/EthProtocolManager.java @@ -146,7 +146,8 @@ public class EthProtocolManager implements ProtocolManager, MinedBlockObserver { LOG.trace("Process message {}, {}", cap, message.getData().getCode()); final EthPeer peer = ethPeers.peer(message.getConnection()); if (peer == null) { - LOG.error("Message received from unknown peer connection: " + message.getConnection()); + LOG.debug( + "Ignoring message received from unknown peer connection: " + message.getConnection()); return; } @@ -229,7 +230,7 @@ public class EthProtocolManager implements ProtocolManager, MinedBlockObserver { LOG.debug("Disconnecting from peer with mismatched network id: {}", status.networkId()); peer.disconnect(DisconnectReason.SUBPROTOCOL_TRIGGERED); } else if (!status.genesisHash().equals(genesisHash)) { - LOG.warn( + LOG.debug( "Disconnecting from peer with matching network id ({}), but non-matching genesis hash: {}", networkId, status.genesisHash()); @@ -239,7 +240,7 @@ public class EthProtocolManager implements ProtocolManager, MinedBlockObserver { peer.registerStatusReceived(status.bestHash(), status.totalDifficulty()); } } catch (final RLPException e) { - LOG.info("Unable to parse status message, disconnecting from peer."); + LOG.debug("Unable to parse status message, disconnecting from peer.", e); // Parsing errors can happen when clients broadcast network ids outside of the int range, // So just disconnect with "subprotocol" error rather than "breach of protocol". peer.disconnect(DisconnectReason.SUBPROTOCOL_TRIGGERED); diff --git a/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/manager/PeerReputation.java b/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/manager/PeerReputation.java index bbdebf57c7..04924ec01e 100644 --- a/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/manager/PeerReputation.java +++ b/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/manager/PeerReputation.java @@ -41,7 +41,7 @@ public class PeerReputation { public Optional recordRequestTimeout(final int requestCode) { final int newTimeoutCount = getOrCreateTimeoutCount(requestCode).incrementAndGet(); if (newTimeoutCount >= TIMEOUT_THRESHOLD) { - LOG.info("Disconnection triggered by repeated timeouts"); + LOG.debug("Disconnection triggered by repeated timeouts"); return Optional.of(DisconnectReason.TIMEOUT); } else { return Optional.empty(); @@ -66,7 +66,7 @@ public class PeerReputation { uselessResponseTimes.poll(); } if (uselessResponseTimes.size() >= USELESS_RESPONSE_THRESHOLD) { - LOG.info("Disconnection triggered by exceeding useless response threshold"); + LOG.debug("Disconnection triggered by exceeding useless response threshold"); return Optional.of(DisconnectReason.USELESS_PEER); } else { return Optional.empty(); diff --git a/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/sync/Downloader.java b/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/sync/Downloader.java index f2a0a16472..4ad33c4162 100644 --- a/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/sync/Downloader.java +++ b/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/sync/Downloader.java @@ -42,6 +42,7 @@ import java.util.Collections; import java.util.Deque; import java.util.List; import java.util.Optional; +import java.util.concurrent.CancellationException; import java.util.concurrent.CompletableFuture; import java.util.concurrent.ConcurrentLinkedDeque; import java.util.concurrent.TimeoutException; @@ -103,7 +104,14 @@ public class Downloader { .whenComplete( (r, t) -> { if (t != null) { - LOG.error("Error encountered while downloading", t); + final Throwable rootCause = ExceptionUtils.rootCause(t); + if (rootCause instanceof CancellationException) { + LOG.trace("Download cancelled", t); + } else if (rootCause instanceof InvalidBlockException) { + LOG.debug("Invalid block downloaded", t); + } else { + LOG.error("Error encountered while downloading", t); + } // On error, wait a bit before retrying ethContext .getScheduler() @@ -160,8 +168,8 @@ public class Downloader { return waitForPeerAndThenSetSyncTarget(); } final SyncTarget syncTarget = syncState.setSyncTarget(bestPeer, target); - LOG.info("Found common ancestor with sync target at block {}", target.getNumber()); - LOG.info("Set sync target: {}.", syncTarget); + LOG.info( + "Found common ancestor with peer {} at block {}", bestPeer, target.getNumber()); syncTargetDisconnectListenerId = bestPeer.subscribeDisconnect(this::onSyncTargetPeerDisconnect); return CompletableFuture.completedFuture(syncTarget); diff --git a/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/sync/tasks/DetermineCommonAncestorTask.java b/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/sync/tasks/DetermineCommonAncestorTask.java index 74e91436df..3bc5e46948 100644 --- a/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/sync/tasks/DetermineCommonAncestorTask.java +++ b/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/sync/tasks/DetermineCommonAncestorTask.java @@ -26,8 +26,11 @@ import java.util.OptionalInt; import java.util.concurrent.CompletableFuture; import com.google.common.annotations.VisibleForTesting; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; public class DetermineCommonAncestorTask extends AbstractEthTask { + private static final Logger LOG = LogManager.getLogger(); private final EthContext ethContext; private final ProtocolSchedule protocolSchedule; private final ProtocolContext protocolContext; @@ -97,7 +100,11 @@ public class DetermineCommonAncestorTask extends AbstractEthTask final int skipInterval = initialQuery ? 0 : calculateSkipInterval(range, headerRequestSize); final int count = initialQuery ? headerRequestSize : calculateCount((double) range, skipInterval); - + LOG.debug( + "Searching for common ancestor with {} between {} and {}", + peer, + minimumPossibleCommonAncestorNumber, + maximumPossibleCommonAncestorNumber); return executeSubTask( () -> GetHeadersFromPeerByNumberTask.endingAtNumber( diff --git a/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/sync/tasks/GetHeadersFromPeerByNumberTask.java b/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/sync/tasks/GetHeadersFromPeerByNumberTask.java index 7111c75d63..456ba727b8 100644 --- a/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/sync/tasks/GetHeadersFromPeerByNumberTask.java +++ b/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/sync/tasks/GetHeadersFromPeerByNumberTask.java @@ -79,7 +79,7 @@ public class GetHeadersFromPeerByNumberTask extends AbstractGetHeadersFromPeerTa @Override protected ResponseStream sendRequest(final EthPeer peer) throws PeerNotConnected { - LOG.info("Requesting {} headers from peer {}.", count, peer); + LOG.debug("Requesting {} headers from peer {}.", count, peer); return peer.getHeadersByNumber(blockNumber, count, reverse, skip); } diff --git a/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/sync/tasks/PipelinedImportChainSegmentTask.java b/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/sync/tasks/PipelinedImportChainSegmentTask.java index ba6621774c..95387073ad 100644 --- a/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/sync/tasks/PipelinedImportChainSegmentTask.java +++ b/ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/sync/tasks/PipelinedImportChainSegmentTask.java @@ -23,6 +23,7 @@ import tech.pegasys.pantheon.ethereum.mainnet.BlockHeaderValidator; import tech.pegasys.pantheon.ethereum.mainnet.HeaderValidationMode; import tech.pegasys.pantheon.ethereum.mainnet.ProtocolSchedule; import tech.pegasys.pantheon.ethereum.mainnet.ProtocolSpec; +import tech.pegasys.pantheon.util.ExceptionUtils; import java.util.ArrayList; import java.util.Arrays; @@ -147,8 +148,8 @@ public class PipelinedImportChainSegmentTask extends AbstractEthTask { reason.name(), connection.getPeer().getClientId()); } catch (final RLPException e) { - // It seems pretty common to get disconnect messages with no reason, which results in an - // rlp parsing error - LOG.warn( - "Received Wire DISCONNECT, but unable to parse reason. Peer: {}", + LOG.debug( + "Received Wire DISCONNECT with invalid RLP. Peer: {}", connection.getPeer().getClientId()); } catch (final Exception e) { LOG.error( diff --git a/ethereum/p2p/src/main/java/tech/pegasys/pantheon/ethereum/p2p/netty/DeFramer.java b/ethereum/p2p/src/main/java/tech/pegasys/pantheon/ethereum/p2p/netty/DeFramer.java index c1ac5443ad..b4db486574 100644 --- a/ethereum/p2p/src/main/java/tech/pegasys/pantheon/ethereum/p2p/netty/DeFramer.java +++ b/ethereum/p2p/src/main/java/tech/pegasys/pantheon/ethereum/p2p/netty/DeFramer.java @@ -21,7 +21,9 @@ import tech.pegasys.pantheon.ethereum.p2p.wire.SubProtocol; import tech.pegasys.pantheon.ethereum.p2p.wire.messages.DisconnectMessage.DisconnectReason; import tech.pegasys.pantheon.ethereum.p2p.wire.messages.HelloMessage; import tech.pegasys.pantheon.ethereum.p2p.wire.messages.WireMessageCodes; +import tech.pegasys.pantheon.ethereum.rlp.RLPException; +import java.io.IOException; import java.util.List; import java.util.concurrent.CompletableFuture; import java.util.concurrent.atomic.AtomicBoolean; @@ -67,7 +69,15 @@ final class DeFramer extends ByteToMessageDecoder { if (!hellosExchanged && message.getCode() == WireMessageCodes.HELLO) { hellosExchanged = true; // Decode first hello and use the payload to modify pipeline - final PeerInfo peerInfo = parsePeerInfo(message); + final PeerInfo peerInfo; + try { + peerInfo = parsePeerInfo(message); + } catch (final RLPException e) { + LOG.debug("Received invalid HELLO message", e); + connectFuture.completeExceptionally(e); + ctx.close(); + return; + } message.release(); LOG.debug("Received HELLO message: {}", peerInfo); if (peerInfo.getVersion() >= 5) { @@ -115,7 +125,12 @@ final class DeFramer extends ByteToMessageDecoder { @Override public void exceptionCaught(final ChannelHandlerContext ctx, final Throwable throwable) throws Exception { - LOG.error("Exception while processing incoming message", throwable); + if (throwable instanceof IOException) { + // IO failures are routine when communicating with random peers across the network. + LOG.debug("IO error while processing incoming message", throwable); + } else { + LOG.error("Exception while processing incoming message", throwable); + } if (connectFuture.isDone()) { connectFuture.get().terminateConnection(DisconnectReason.TCP_SUBSYSTEM_ERROR, false); } else { diff --git a/ethereum/p2p/src/main/java/tech/pegasys/pantheon/ethereum/p2p/wire/Capability.java b/ethereum/p2p/src/main/java/tech/pegasys/pantheon/ethereum/p2p/wire/Capability.java index ea23d1013b..3e67caba35 100644 --- a/ethereum/p2p/src/main/java/tech/pegasys/pantheon/ethereum/p2p/wire/Capability.java +++ b/ethereum/p2p/src/main/java/tech/pegasys/pantheon/ethereum/p2p/wire/Capability.java @@ -21,9 +21,6 @@ import tech.pegasys.pantheon.util.bytes.BytesValues; import java.nio.charset.StandardCharsets; import java.util.Objects; -import org.apache.logging.log4j.LogManager; -import org.apache.logging.log4j.Logger; - /** * Represents a client capability. * @@ -32,16 +29,10 @@ import org.apache.logging.log4j.Logger; * format */ public class Capability { - private static final Logger LOG = LogManager.getLogger(); private final String name; private final int version; private Capability(final String name, final int version) { - // Quorum reports IBFT as "istanbul", breaking wire protocol conventions. - // As such, this check cannot prevent connection. - if (name.length() != 3) { - LOG.warn("Capability name '{}' is too long", name); - } this.name = name; this.version = version; }