Additional logging details for IBFT (#650)

Signed-off-by: Adrian Sutton <adrian.sutton@consensys.net>
pull/2/head
Jason Frame 6 years ago committed by GitHub
parent 5da878f3e0
commit 5f0434e9e5
  1. 12
      consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/IbftExtraData.java
  2. 1
      consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/IbftProcessor.java
  3. 2
      consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/blockcreation/IbftMiningCoordinator.java
  4. 5
      consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/headervalidationrules/IbftCoinbaseValidationRule.java
  5. 5
      consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/headervalidationrules/IbftCommitSealsValidationRule.java
  6. 7
      consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftDiscardValidatorVote.java
  7. 5
      consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftGetValidatorsByBlockHash.java
  8. 5
      consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftGetValidatorsByBlockNumber.java
  9. 10
      consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/jsonrpc/methods/IbftProposeValidatorVote.java
  10. 7
      consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/network/ValidatorPeers.java
  11. 21
      consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/IbftBlockHeightManager.java
  12. 47
      consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/IbftController.java
  13. 41
      consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/IbftRound.java
  14. 16
      consensus/ibft/src/main/java/tech/pegasys/pantheon/consensus/ibft/statemachine/RoundState.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();
}
}

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

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

@ -44,7 +44,10 @@ public class IbftCoinbaseValidationRule implements AttachedBlockHeaderValidation
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;
}

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

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

@ -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> blockHeader = blockchain.getBlockHeader(hash);
return blockHeader
.map(

@ -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> blockHeader =
blockchainQueries().getBlockHeaderByNumber(blockNumber);
LOG.trace("Received RPC rpcName={} block={}", getName(), blockNumber);
return blockHeader
.map(
header ->

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

@ -75,6 +75,8 @@ public class ValidatorPeers implements ValidatorMulticaster, PeerConnectionTrack
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 @@ 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());
}
});
}

@ -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> preparedCertificate =
currentRound.createPrepareCertificate();
@ -150,21 +155,21 @@ public class IbftBlockHeightManager implements BlockHeightManager {
@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 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) {

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

@ -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<ProposalPayload> 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<PreparePayload> msg) {
LOG.info("Received a prepare message.");
LOG.debug("Received a prepare message. round={}", roundState.getRoundIdentifier());
peerIsPrepared(msg);
}
public void handleCommitMessage(final SignedData<CommitPayload> 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);
}

@ -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<PreparePayload> 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<CommitPayload> 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<Block> getProposedBlock() {

Loading…
Cancel
Save