[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.

ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/manager/AbstractRetryingPeerTask.java

@@ -84,7 +84,7 @@ public abstract class AbstractRetryingPeerTask<T> extends AbstractEthTask<T> {
       return;
     }
 
-    LOG.info(
+    LOG.debug(
         "Retrying after recoverable failure from peer task {}: {}",
         this.getClass().getSimpleName(),
         cause.getMessage());

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);

ethereum/eth/src/main/java/tech/pegasys/pantheon/ethereum/eth/manager/PeerReputation.java

@@ -41,7 +41,7 @@ public class PeerReputation {
   public Optional<DisconnectReason> 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();

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<C> {
             .whenComplete(
                 (r, t) -> {
                   if (t != null) {
+                    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<C> {
                   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);

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<C> extends AbstractEthTask<BlockHeader> {
+  private static final Logger LOG = LogManager.getLogger();
   private final EthContext ethContext;
   private final ProtocolSchedule<C> protocolSchedule;
   private final ProtocolContext<C> protocolContext;
@@ -97,7 +100,11 @@ public class DetermineCommonAncestorTask<C> extends AbstractEthTask<BlockHeader>
     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(

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);
   }
 

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<C> extends AbstractEthTask<List<Blo
       LOG.warn(
           "Import of chain segment ({} to {}) failed: {}.",
           firstHeader().getNumber(),
-          lastHeader().getNumber());
-      LOG.error("Error", throwable);
+          lastHeader().getNumber(),
+          ExceptionUtils.rootCause(throwable).getMessage());
       result.get().completeExceptionally(throwable);
     } else {
       importedBlocks.addAll(blocks);

ethereum/p2p/src/main/java/tech/pegasys/pantheon/ethereum/p2p/netty/AbstractHandshakeHandler.java

@@ -122,7 +122,7 @@ abstract class AbstractHandshakeHandler extends SimpleChannelInboundHandler<Byte
 
   @Override
   public void exceptionCaught(final ChannelHandlerContext ctx, final Throwable throwable) {
-    LOG.warn("Handshake error:", throwable.getMessage());
+    LOG.debug("Handshake error:", throwable);
     connectionFuture.completeExceptionally(throwable);
     ctx.close();
   }

ethereum/p2p/src/main/java/tech/pegasys/pantheon/ethereum/p2p/netty/ApiHandler.java

@@ -82,10 +82,8 @@ final class ApiHandler extends SimpleChannelInboundHandler<MessageData> {
                 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(

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 {
+    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 {

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</a>
  */
 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;
   }