From 5f0434e9e5f7c7f6c297566959a211f065410e9f Mon Sep 17 00:00:00 2001 From: Jason Frame Date: Fri, 25 Jan 2019 16:21:29 +1000 Subject: [PATCH] Additional logging details for IBFT (#650) Signed-off-by: Adrian Sutton --- .../consensus/ibft/IbftExtraData.java | 12 +++++ .../consensus/ibft/IbftProcessor.java | 1 + .../blockcreation/IbftMiningCoordinator.java | 2 +- .../IbftCoinbaseValidationRule.java | 5 +- .../IbftCommitSealsValidationRule.java | 5 +- .../methods/IbftDiscardValidatorVote.java | 7 ++- .../methods/IbftGetValidatorsByBlockHash.java | 5 ++ .../IbftGetValidatorsByBlockNumber.java | 5 ++ .../methods/IbftProposeValidatorVote.java | 10 ++++ .../ibft/network/ValidatorPeers.java | 7 ++- .../statemachine/IbftBlockHeightManager.java | 21 +++++---- .../ibft/statemachine/IbftController.java | 47 ++++++++++++++----- .../ibft/statemachine/IbftRound.java | 41 +++++++++++----- .../ibft/statemachine/RoundState.java | 16 +++++-- 14 files changed, 144 insertions(+), 40 deletions(-) diff --git a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/IbftExtraData.java b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/IbftExtraData.java index e739fd6537..7ca182c560 100644 --- a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/IbftExtraData.java +++ b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/IbftExtraData.java @@ -26,6 +26,7 @@ import java.util.Collection; 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 class IbftExtraData { 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(); + } } diff --git a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/IbftProcessor.java b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/IbftProcessor.java index 6dc9c37576..1c6a1a5796 100644 --- a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/IbftProcessor.java +++ b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/IbftProcessor.java @@ -67,6 +67,7 @@ public class IbftProcessor implements Runnable { 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(); } diff --git a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/blockcreation/IbftMiningCoordinator.java b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/blockcreation/IbftMiningCoordinator.java index 2f75979ec0..3327469489 100644 --- a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/blockcreation/IbftMiningCoordinator.java +++ b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/blockcreation/IbftMiningCoordinator.java @@ -77,8 +77,8 @@ public class IbftMiningCoordinator implements MiningCoordinator, BlockAddedObser @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())); } } diff --git a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/headervalidationrules/IbftCoinbaseValidationRule.java b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/headervalidationrules/IbftCoinbaseValidationRule.java index 9dd8642355..733398f7f8 100644 --- a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/headervalidationrules/IbftCoinbaseValidationRule.java +++ b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/headervalidationrules/IbftCoinbaseValidationRule.java @@ -44,7 +44,10 @@ public class IbftCoinbaseValidationRule implements AttachedBlockHeaderValidation final Collection
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; } diff --git a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/headervalidationrules/IbftCommitSealsValidationRule.java b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/headervalidationrules/IbftCommitSealsValidationRule.java index 81388085ea..3e5672f4dd 100644 --- a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/headervalidationrules/IbftCommitSealsValidationRule.java +++ b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/headervalidationrules/IbftCommitSealsValidationRule.java @@ -67,7 +67,10 @@ public class IbftCommitSealsValidationRule } 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; } diff --git a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftDiscardValidatorVote.java b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftDiscardValidatorVote.java index 14951d470a..b11ac0a0d4 100644 --- a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftDiscardValidatorVote.java +++ b/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.parameters.JsonRpcParamet 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 class IbftDiscardValidatorVote implements JsonRpcMethod { @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); diff --git a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftGetValidatorsByBlockHash.java b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftGetValidatorsByBlockHash.java index 19f5edebb9..dccc43b211 100644 --- a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftGetValidatorsByBlockHash.java +++ b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftGetValidatorsByBlockHash.java @@ -25,7 +25,11 @@ import tech.pegasys.pantheon.ethereum.jsonrpc.internal.response.JsonRpcSuccessRe 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 class IbftGetValidatorsByBlockHash implements JsonRpcMethod { 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 = blockchain.getBlockHeader(hash); return blockHeader .map( diff --git a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftGetValidatorsByBlockNumber.java b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftGetValidatorsByBlockNumber.java index 8faf0332aa..f07ce98a21 100644 --- a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftGetValidatorsByBlockNumber.java +++ b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftGetValidatorsByBlockNumber.java @@ -24,8 +24,12 @@ import tech.pegasys.pantheon.ethereum.jsonrpc.internal.queries.BlockchainQueries 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 @@ public class IbftGetValidatorsByBlockNumber extends AbstractBlockParameterMethod protected Object resultByBlockNumber(final JsonRpcRequest request, final long blockNumber) { final Optional blockHeader = blockchainQueries().getBlockHeaderByNumber(blockNumber); + LOG.trace("Received RPC rpcName={} block={}", getName(), blockNumber); return blockHeader .map( header -> diff --git a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftProposeValidatorVote.java b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftProposeValidatorVote.java index 9217e2e21e..0862b40aac 100644 --- a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftProposeValidatorVote.java +++ b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftProposeValidatorVote.java @@ -13,6 +13,7 @@ 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; @@ -20,7 +21,11 @@ import tech.pegasys.pantheon.ethereum.jsonrpc.internal.parameters.JsonRpcParamet 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 class IbftProposeValidatorVote implements JsonRpcMethod { 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); diff --git a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/network/ValidatorPeers.java b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/network/ValidatorPeers.java index ffdcea6d49..d15929fe10 100644 --- a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/network/ValidatorPeers.java +++ b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/network/ValidatorPeers.java @@ -75,6 +75,8 @@ public class ValidatorPeers implements ValidatorMulticaster, PeerConnectionTrack private void sendMessageToSpecificAddresses( final Collection
recipients, final MessageData message) { + LOG.trace( + "Sending message to peers messageCode={} recipients={}", message.getCode(), recipients); recipients .stream() .map(peerConnections::get) @@ -84,7 +86,10 @@ public class ValidatorPeers implements ValidatorMulticaster, PeerConnectionTrack 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()); } }); } diff --git a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/IbftBlockHeightManager.java b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/IbftBlockHeightManager.java index 42a39e3cc1..10716e5bf1 100644 --- a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/IbftBlockHeightManager.java +++ b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/IbftBlockHeightManager.java @@ -124,11 +124,16 @@ public class IbftBlockHeightManager implements BlockHeightManager { @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 = currentRound.createPrepareCertificate(); @@ -150,21 +155,21 @@ public class IbftBlockHeightManager implements BlockHeightManager { @Override public void handleProposalPayload(final SignedData 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 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 payload) { - LOG.info("Received a commit Payload."); + LOG.debug("Received a Commit Payload."); actionOrBufferMessage(payload, currentRound::handleCommitMessage, RoundState::addCommitMessage); } @@ -192,7 +197,7 @@ public class IbftBlockHeightManager implements BlockHeightManager { 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 class IbftBlockHeightManager implements BlockHeightManager { 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) { diff --git a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/IbftController.java b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/IbftController.java index 749feb6171..6c48df8fd1 100644 --- a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/IbftController.java +++ b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/IbftController.java @@ -127,7 +127,9 @@ public class IbftController { 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())); } } @@ -135,6 +137,10 @@ public class IbftController { final Message message, final SignedData

signedPayload, final Consumer> handleMessage) { + LOG.debug( + "Received IBFT message messageType={} payload={}", + signedPayload.getPayload().getMessageType(), + signedPayload); if (processMessage(signedPayload, message)) { gossiper.gossipMessage(message); handleMessage.accept(signedPayload); @@ -145,15 +151,24 @@ public class IbftController { 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; } @@ -161,10 +176,14 @@ public class IbftController { } 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()); } } @@ -172,7 +191,10 @@ public class IbftController { 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()); } } @@ -180,8 +202,7 @@ public class IbftController { currentHeightManager = ibftBlockHeightManagerFactory.create(parentHeader); currentHeightManager.start(); final long newChainHeight = currentHeightManager.getChainHeight(); - final List orDefault = futureMessages.getOrDefault(newChainHeight, emptyList()); - orDefault.forEach(this::handleMessage); + futureMessages.getOrDefault(newChainHeight, emptyList()).forEach(this::handleMessage); futureMessages.remove(newChainHeight); } @@ -192,7 +213,11 @@ public class IbftController { } 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; } diff --git a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/IbftRound.java b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/IbftRound.java index b9d7cc4d85..e8da16c704 100644 --- a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/IbftRound.java +++ b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/IbftRound.java @@ -84,8 +84,13 @@ public class IbftRound { } public void createAndSendProposalMessage(final long headerTimeStampSeconds) { - LOG.info("Creating proposed block."); final Block block = blockCreator.createBlock(headerTimeStampSeconds); + final IbftExtraData extraData = IbftExtraData.decode(block.getHeader().getExtraData()); + LOG.info( + "Creating proposed block. round={} extraData={} blockHeader={}", + roundState.getRoundIdentifier(), + extraData, + block.getHeader()); transmitter.multicastProposal(roundState.getRoundIdentifier(), block); updateStateWithProposedBlock( @@ -99,11 +104,13 @@ public class IbftRound { SignedData proposal; if (!latestCertificate.isPresent()) { - LOG.info("Multicasting NewRound with new block."); + LOG.trace("Multicasting NewRound with new block. round={}", roundState.getRoundIdentifier()); final Block block = blockCreator.createBlock(headerTimestamp); proposal = messageFactory.createSignedProposalPayload(getRoundIdentifier(), block); } else { - LOG.info("Multicasting NewRound from PreparedCertificate."); + LOG.trace( + "Multicasting NewRound from PreparedCertificate. round={}", + roundState.getRoundIdentifier()); proposal = createProposalFromPreparedCertificate(latestCertificate.get()); } transmitter.multicastNewRound(getRoundIdentifier(), roundChangeCertificate, proposal); @@ -132,6 +139,10 @@ public class IbftRound { blockHeader, extraDataToPublish)); final BlockHeader newHeader = headerBuilder.buildBlockHeader(); final Block newBlock = new Block(newHeader, block.getBody()); + LOG.debug( + "Created proposal from prepared certificate blockHeader={} extraData={}", + block.getHeader(), + extraDataToPublish); return messageFactory.createSignedProposalPayload(getRoundIdentifier(), newBlock); } @@ -139,7 +150,7 @@ public class IbftRound { LOG.info("Handling a Proposal message."); if (getRoundIdentifier().getRoundNumber() != 0) { - LOG.info("Illegally received a Proposal message when not in Round 0."); + LOG.error("Illegally received a Proposal message when not in Round 0."); return; } actionReceivedProposal(msg); @@ -149,7 +160,7 @@ public class IbftRound { LOG.info("Handling a New Round Proposal."); if (getRoundIdentifier().getRoundNumber() == 0) { - LOG.info("Illegally received a NewRound message when in Round 0."); + LOG.error("Illegally received a NewRound message when in Round 0."); return; } actionReceivedProposal(msg.getPayload().getProposalPayload()); @@ -169,12 +180,12 @@ public class IbftRound { } public void handlePrepareMessage(final SignedData msg) { - LOG.info("Received a prepare message."); + LOG.debug("Received a prepare message. round={}", roundState.getRoundIdentifier()); peerIsPrepared(msg); } public void handleCommitMessage(final SignedData msg) { - LOG.info("Received a commit message."); + LOG.debug("Received a commit message. round={}", roundState.getRoundIdentifier()); peerIsCommitted(msg); } @@ -189,7 +200,7 @@ public class IbftRound { if (blockAccepted) { // There are times handling a proposed block is enough to enter prepared. if (wasPrepared != roundState.isPrepared()) { - LOG.info("Sending commit message."); + LOG.debug("Sending commit message. round={}", roundState.getRoundIdentifier()); final Block block = roundState.getProposedBlock().get(); transmitter.multicastCommit(getRoundIdentifier(), block.getHash(), createCommitSeal(block)); } @@ -212,7 +223,7 @@ public class IbftRound { final boolean wasPrepared = roundState.isPrepared(); roundState.addPrepareMessage(msg); if (wasPrepared != roundState.isPrepared()) { - LOG.info("Sending commit message."); + LOG.debug("Sending commit message. round={}", roundState.getRoundIdentifier()); final Block block = roundState.getProposedBlock().get(); transmitter.multicastCommit(getRoundIdentifier(), block.getHash(), createCommitSeal(block)); } @@ -231,11 +242,17 @@ public class IbftRound { IbftHelpers.createSealedBlock( roundState.getProposedBlock().get(), roundState.getCommitSeals()); - LOG.info("Importing block to chain."); - boolean result = + final long blockNumber = blockToImport.getHeader().getNumber(); + final IbftExtraData extraData = IbftExtraData.decode(blockToImport.getHeader().getExtraData()); + LOG.info("Importing block to chain. block={} extraData={}", blockNumber, extraData); + final boolean result = blockImporter.importBlock(protocolContext, blockToImport, HeaderValidationMode.FULL); if (!result) { - LOG.info("Failed to import block to chain."); + LOG.error( + "Failed to import block to chain. block={} extraData={} blockHeader={}", + blockNumber, + extraData, + blockToImport.getHeader()); } else { notifyNewBlockListeners(blockToImport); } diff --git a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/RoundState.java b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/RoundState.java index b883909407..e63a62a01e 100644 --- a/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/RoundState.java +++ b/consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/RoundState.java @@ -30,9 +30,12 @@ import java.util.Set; import java.util.stream.Collectors; import com.google.common.collect.Sets; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; // Data items used to define how a round will operate public class RoundState { + private static final Logger LOG = LogManager.getLogger(); private final ConsensusRoundIdentifier roundIdentifier; private final MessageValidator validator; @@ -79,6 +82,7 @@ public class RoundState { public void addPrepareMessage(final SignedData msg) { if (!proposalMessage.isPresent() || validator.validatePrepareMessage(msg)) { preparePayloads.add(msg); + LOG.debug("Round state added prepare message prepare={}", msg); } updateState(); } @@ -86,6 +90,7 @@ public class RoundState { public void addCommitMessage(final SignedData msg) { if (!proposalMessage.isPresent() || validator.validateCommmitMessage(msg)) { commitPayloads.add(msg); + LOG.debug("Round state added commit message commit={}", msg); } updateState(); @@ -94,10 +99,15 @@ public class RoundState { private void updateState() { // NOTE: The quorum for Prepare messages is 1 less than the quorum size as the proposer // does not supply a prepare message - prepared = - (preparePayloads.size() >= prepareMessageCountForQuorum(quorum)) - && proposalMessage.isPresent(); + final long prepareQuorum = prepareMessageCountForQuorum(quorum); + prepared = (preparePayloads.size() >= prepareQuorum) && proposalMessage.isPresent(); committed = (commitPayloads.size() >= quorum) && proposalMessage.isPresent(); + LOG.debug( + "Round state updated prepared={} committed={} prepareQuorum={} quorum={}", + prepared, + committed, + prepareQuorum, + quorum); } public Optional getProposedBlock() {