Additional logging details for IBFT (PegaSysEng#650)

consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/IbftExtraData.java

@@ -26,6 +26,7 @@
 import java.util.Collections;
 import java.util.List;
 import java.util.Optional;
+import java.util.StringJoiner;
 
 /**
  * Represents the data structure stored in the extraData field of the BlockHeader used when
@@ -155,4 +156,15 @@ public Optional<Vote> getVote() {
   public int getRound() {
     return round;
   }
+
+  @Override
+  public String toString() {
+    return new StringJoiner(", ", IbftExtraData.class.getSimpleName() + "[", "]")
+        .add("vanityData=" + vanityData)
+        .add("seals=" + seals)
+        .add("vote=" + vote)
+        .add("round=" + round)
+        .add("validators=" + validators)
+        .toString();
+  }
 }

consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/IbftProcessor.java

@@ -67,6 +67,7 @@ public void run() {
       nextIbftEvent().ifPresent(event -> eventMultiplexer.handleIbftEvent(event));
     }
     // Clean up the executor service the round timer has been utilising
+    LOG.info("Shutting down IBFT event processor");
     roundTimerExecutor.shutdownNow();
   }
 

consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/blockcreation/IbftMiningCoordinator.java

@@ -77,8 +77,8 @@ public void setExtraData(final BytesValue extraData) {
 
   @Override
   public void onBlockAdded(final BlockAddedEvent event, final Blockchain blockchain) {
-    LOG.info("New canonical head detected. {} ", event.isNewCanonicalHead());
     if (event.isNewCanonicalHead()) {
+      LOG.info("New canonical head detected");
       eventQueue.add(new NewChainHead(event.getBlock().getHeader()));
     }
   }

consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/headervalidationrules/IbftCoinbaseValidationRule.java

@@ -44,7 +44,10 @@ public boolean validate(
     final Collection<Address> storedValidators = validatorProvider.getValidators();
 
     if (!storedValidators.contains(proposer)) {
-      LOGGER.trace("Block proposer is not a member of the validators.");
+      LOGGER.trace(
+          "Block proposer is not a member of the validators. proposer={}, validators={}",
+          proposer,
+          storedValidators);
       return false;
     }
 

consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/headervalidationrules/IbftCommitSealsValidationRule.java

@@ -67,7 +67,10 @@ private boolean validateCommitters(
     }
 
     if (!storedValidators.containsAll(committers)) {
-      LOGGER.trace("Not all committers are in the locally maintained validator list.");
+      LOGGER.trace(
+          "Not all committers are in the locally maintained validator list. validators={} committers={}",
+          storedValidators,
+          committers);
       return false;
     }
 

consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftDiscardValidatorVote.java

@@ -20,7 +20,11 @@
 import tech.pegasys.pantheon.ethereum.jsonrpc.internal.response.JsonRpcResponse;
 import tech.pegasys.pantheon.ethereum.jsonrpc.internal.response.JsonRpcSuccessResponse;
 
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+
 public class IbftDiscardValidatorVote implements JsonRpcMethod {
+  private static final Logger LOG = LogManager.getLogger();
   private final VoteProposer voteProposer;
   private final JsonRpcParameter parameters;
 
@@ -37,9 +41,8 @@ public String getName() {
 
   @Override
   public JsonRpcResponse response(final JsonRpcRequest req) {
-
     final Address validatorAddress = parameters.required(req.getParams(), 0, Address.class);
-
+    LOG.trace("Received RPC rpcName={} address={}", getName(), validatorAddress);
     voteProposer.discard(validatorAddress);
 
     return new JsonRpcSuccessResponse(req.getId(), true);

consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftGetValidatorsByBlockHash.java

@@ -25,7 +25,11 @@
 import java.util.Optional;
 import java.util.stream.Collectors;
 
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+
 public class IbftGetValidatorsByBlockHash implements JsonRpcMethod {
+  private static final Logger LOG = LogManager.getLogger();
 
   private final Blockchain blockchain;
   private final BlockInterface blockInterface;
@@ -52,6 +56,7 @@ public JsonRpcResponse response(final JsonRpcRequest request) {
 
   private Object blockResult(final JsonRpcRequest request) {
     final Hash hash = parameters.required(request.getParams(), 0, Hash.class);
+    LOG.trace("Received RPC rpcName={} blockHash={}", getName(), hash);
     final Optional<BlockHeader> blockHeader = blockchain.getBlockHeader(hash);
     return blockHeader
         .map(

consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftGetValidatorsByBlockNumber.java

@@ -24,8 +24,12 @@
 import java.util.Optional;
 import java.util.stream.Collectors;
 
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+
 public class IbftGetValidatorsByBlockNumber extends AbstractBlockParameterMethod
     implements JsonRpcMethod {
+  private static final Logger LOG = LogManager.getLogger();
 
   private final BlockInterface blockInterface;
 
@@ -46,6 +50,7 @@ protected BlockParameter blockParameter(final JsonRpcRequest request) {
   protected Object resultByBlockNumber(final JsonRpcRequest request, final long blockNumber) {
     final Optional<BlockHeader> blockHeader =
         blockchainQueries().getBlockHeaderByNumber(blockNumber);
+    LOG.trace("Received RPC rpcName={} block={}", getName(), blockNumber);
     return blockHeader
         .map(
             header ->

consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftProposeValidatorVote.java

@@ -13,14 +13,19 @@
 package tech.pegasys.pantheon.consensus.ibft.jsonrpc.methods;
 
 import tech.pegasys.pantheon.consensus.common.VoteProposer;
+import tech.pegasys.pantheon.consensus.common.VoteType;
 import tech.pegasys.pantheon.ethereum.core.Address;
 import tech.pegasys.pantheon.ethereum.jsonrpc.internal.JsonRpcRequest;
 import tech.pegasys.pantheon.ethereum.jsonrpc.internal.methods.JsonRpcMethod;
 import tech.pegasys.pantheon.ethereum.jsonrpc.internal.parameters.JsonRpcParameter;
 import tech.pegasys.pantheon.ethereum.jsonrpc.internal.response.JsonRpcResponse;
 import tech.pegasys.pantheon.ethereum.jsonrpc.internal.response.JsonRpcSuccessResponse;
 
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+
 public class IbftProposeValidatorVote implements JsonRpcMethod {
+  private static final Logger LOG = LogManager.getLogger();
   private final VoteProposer voteProposer;
   private final JsonRpcParameter parameters;
 
@@ -40,6 +45,11 @@ public JsonRpcResponse response(final JsonRpcRequest req) {
 
     final Address validatorAddress = parameters.required(req.getParams(), 0, Address.class);
     final Boolean add = parameters.required(req.getParams(), 1, Boolean.class);
+    LOG.trace(
+        "Received RPC rpcName={} voteType={} address={}",
+        getName(),
+        add ? VoteType.ADD : VoteType.DROP,
+        validatorAddress);
 
     if (add) {
       voteProposer.auth(validatorAddress);

consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/network/ValidatorPeers.java

@@ -75,6 +75,8 @@ public void send(final MessageData message, final Collection<Address> blackList)
 
   private void sendMessageToSpecificAddresses(
       final Collection<Address> recipients, final MessageData message) {
+    LOG.trace(
+        "Sending message to peers messageCode={} recipients={}", message.getCode(), recipients);
     recipients
         .stream()
         .map(peerConnections::get)
@@ -84,7 +86,10 @@ private void sendMessageToSpecificAddresses(
               try {
                 connection.sendForProtocol(PROTOCOL_NAME, message);
               } catch (final PeerNotConnected peerNotConnected) {
-                LOG.trace("Lost connection to a validator.");
+                LOG.trace(
+                    "Lost connection to a validator. remoteAddress={} peerInfo={}",
+                    connection.getRemoteAddress(),
+                    connection.getPeer());
               }
             });
   }

consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/IbftBlockHeightManager.java

@@ -124,11 +124,16 @@ public void handleBlockTimerExpiry(final ConsensusRoundIdentifier roundIdentifie
   @Override
   public void roundExpired(final RoundExpiry expire) {
     if (!expire.getView().equals(currentRound.getRoundIdentifier())) {
-      LOG.info("Ignoring Round timer expired which does not match current round.");
+      LOG.info(
+          "Ignoring Round timer expired which does not match current round. round={}, timerRound={}",
+          currentRound.getRoundIdentifier(),
+          expire.getView());
       return;
     }
 
-    LOG.info("Round has expired, creating PreparedCertificate and notifying peers.");
+    LOG.info(
+        "Round has expired, creating PreparedCertificate and notifying peers. round={}",
+        currentRound.getRoundIdentifier());
     final Optional<PreparedCertificate> preparedCertificate =
         currentRound.createPrepareCertificate();
 
@@ -150,21 +155,21 @@ public void roundExpired(final RoundExpiry expire) {
 
   @Override
   public void handleProposalPayload(final SignedData<ProposalPayload> signedPayload) {
-    LOG.info("Received a Proposal Payload.");
+    LOG.debug("Received a Proposal Payload.");
     actionOrBufferMessage(
         signedPayload, currentRound::handleProposalMessage, RoundState::setProposedBlock);
   }
 
   @Override
   public void handlePreparePayload(final SignedData<PreparePayload> signedPayload) {
-    LOG.info("Received a prepare Payload.");
+    LOG.debug("Received a Prepare Payload.");
     actionOrBufferMessage(
         signedPayload, currentRound::handlePrepareMessage, RoundState::addPrepareMessage);
   }
 
   @Override
   public void handleCommitPayload(final SignedData<CommitPayload> payload) {
-    LOG.info("Received a commit Payload.");
+    LOG.debug("Received a Commit Payload.");
     actionOrBufferMessage(payload, currentRound::handleCommitMessage, RoundState::addCommitMessage);
   }
 
@@ -192,7 +197,7 @@ public void handleRoundChangePayload(final SignedData<RoundChangePayload> signed
 
     final MessageAge messageAge = determineAgeOfPayload(signedPayload.getPayload());
     if (messageAge == PRIOR_ROUND) {
-      LOG.info("Received RoundChange Payload for a prior round.");
+      LOG.debug("Received RoundChange Payload for a prior round. targetRound={}", targetRound);
       return;
     }
 
@@ -230,10 +235,10 @@ public void handleNewRoundPayload(final SignedData<NewRoundPayload> signedPayloa
     final MessageAge messageAge = determineAgeOfPayload(payload);
 
     if (messageAge == PRIOR_ROUND) {
-      LOG.info("Received NewRound Payload for a prior round.");
+      LOG.info("Received NewRound Payload for a prior round={}", payload.getRoundIdentifier());
       return;
     }
-    LOG.info("Received NewRound Payload for {}", payload.getRoundIdentifier().toString());
+    LOG.info("Received NewRound Payload for {}", payload.getRoundIdentifier());
 
     if (newRoundMessageValidator.validateNewRoundMessage(signedPayload)) {
       if (messageAge == FUTURE_ROUND) {

consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/IbftController.java

@@ -124,14 +124,20 @@ private void handleMessage(final Message message) {
 
       default:
         throw new IllegalArgumentException(
-            "Received message does not conform to any recognised IBFT message structure.");
+            String.format(
+                "Received message with messageCode=%d does not conform to any recognised IBFT message structure",
+                message.getData().getCode()));
     }
   }
 
   private <P extends Payload> void consumeMessage(
       final Message message,
       final SignedData<P> signedPayload,
       final Consumer<SignedData<P>> handleMessage) {
+    LOG.debug(
+        "Received IBFT message messageType={} payload={}",
+        signedPayload.getPayload().getMessageType(),
+        signedPayload);
     if (processMessage(signedPayload, message)) {
       gossiper.gossipMessage(message);
       handleMessage.accept(signedPayload);
@@ -142,43 +148,58 @@ public void handleNewBlockEvent(final NewChainHead newChainHead) {
     final BlockHeader newBlockHeader = newChainHead.getNewChainHeadHeader();
     final BlockHeader currentMiningParent = currentHeightManager.getParentBlockHeader();
     if (newBlockHeader.getNumber() < currentMiningParent.getNumber()) {
-      LOG.info("Discarding NewChainHead event, was for previous block height.");
+      LOG.debug(
+          "Discarding NewChainHead event, was for previous block height. chainHeight={} eventHeight={}",
+          currentMiningParent.getNumber(),
+          newBlockHeader.getNumber());
       return;
     }
 
     if (newBlockHeader.getNumber() == currentMiningParent.getNumber()) {
       if (newBlockHeader.getHash().equals(currentMiningParent.getHash())) {
-        LOG.info("Discarding duplicate NewChainHead event.");
+        LOG.debug(
+            "Discarding duplicate NewChainHead event. chainHeight={} newBlockHash={} parentBlockHash",
+            newBlockHeader.getNumber(),
+            newBlockHeader.getHash(),
+            currentMiningParent.getHash());
       } else {
-        LOG.error("Subsequent NewChainHead event at same block height indicates chain fork.");
+        LOG.error(
+            "Subsequent NewChainHead event at same block height indicates chain fork. chainHeight={}",
+            currentMiningParent.getNumber());
       }
       return;
     }
     startNewHeightManager(newBlockHeader);
   }
 
   public void handleBlockTimerExpiry(final BlockTimerExpiry blockTimerExpiry) {
-    if (isMsgForCurrentHeight(blockTimerExpiry.getRoundIndentifier())) {
-      currentHeightManager.handleBlockTimerExpiry(blockTimerExpiry.getRoundIndentifier());
+    final ConsensusRoundIdentifier roundIndentifier = blockTimerExpiry.getRoundIndentifier();
+    if (isMsgForCurrentHeight(roundIndentifier)) {
+      currentHeightManager.handleBlockTimerExpiry(roundIndentifier);
     } else {
-      LOG.info("Block timer event discarded as it is not for current block height");
+      LOG.debug(
+          "Block timer event discarded as it is not for current block height chainHeight={} eventHeight={}",
+          currentHeightManager.getChainHeight(),
+          roundIndentifier.getSequenceNumber());
     }
   }
 
   public void handleRoundExpiry(final RoundExpiry roundExpiry) {
     if (isMsgForCurrentHeight(roundExpiry.getView())) {
       currentHeightManager.roundExpired(roundExpiry);
     } else {
-      LOG.info("Round expiry event discarded as it is not for current block height");
+      LOG.debug(
+          "Round expiry event discarded as it is not for current block height chainHeight={} eventHeight={}",
+          currentHeightManager.getChainHeight(),
+          roundExpiry.getView().getSequenceNumber());
     }
   }
 
   private void startNewHeightManager(final BlockHeader parentHeader) {
     currentHeightManager = ibftBlockHeightManagerFactory.create(parentHeader);
     currentHeightManager.start();
     final long newChainHeight = currentHeightManager.getChainHeight();
-    final List<Message> orDefault = futureMessages.getOrDefault(newChainHeight, emptyList());
-    orDefault.forEach(this::handleMessage);
+    futureMessages.getOrDefault(newChainHeight, emptyList()).forEach(this::handleMessage);
     futureMessages.remove(newChainHeight);
   }
 
@@ -189,7 +210,11 @@ private boolean processMessage(final SignedData<? extends Payload> msg, final Me
     } else if (isMsgForFutureChainHeight(msgRoundIdentifier)) {
       addMessageToFutureMessageBuffer(msgRoundIdentifier.getSequenceNumber(), rawMsg);
     } else {
-      LOG.info("IBFT message discarded as it is from a previous block height");
+      LOG.debug(
+          "IBFT message discarded as it is from a previous block height messageType={} chainHeight={} eventHeight={}",
+          msg.getPayload().getMessageType(),
+          currentHeightManager.getChainHeight(),
+          msgRoundIdentifier.getSequenceNumber());
     }
     return false;
   }