Additional logging details for IBFT #650

jframe · 2019-01-24T05:14:49Z

PR description

This adds some additional logging in IBFT. It is mostly centred on logging details in the state machine.
I'm also name=value pairs for the additional data that is being logged both so it is easier to parse (both manually and with logging tools).
Also lowered some of the existing INFO logging levels to DEBUG.

Fixed Issue(s)

…e message type

CjHare

LGTM

rain-on · 2019-01-24T09:18:52Z

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

@@ -75,6 +75,11 @@ 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={} messageData={} recipients={}",


the message data contained might be useful - but I suspect that given its a byte array, our ability to deconstruct it might be ... hard.

it will be difficult to deconstruct, I was considering leaving it out. thinking about it more I don't think it is useful especially since the raw packet is already logged by netty.

rain-on · 2019-01-24T09:20:21Z

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

@@ -84,7 +89,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={}",


If we want to know when we gain/lose validators, we should log that in the add/remove? An error here means we literally ran into the someone disconnected between creating the stream and getting to their turn.

I think we do want to know when we gain/remove validators. I've just added additional details to the existing log so we know who peer got disconnected.

we should log that in the add/remove - not in this exception - in fact, this exception BORDERLINE doesn't need info in it...

rain-on · 2019-01-24T09:22:00Z

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

    actionOrBufferMessage(
        signedPayload, currentRound::handleProposalMessage, RoundState::setProposedBlock);
  }

  public void handlePreparePayload(final SignedData<PreparePayload> signedPayload) {
-    LOG.info("Received a prepare Payload.");
+    LOG.debug("Received a prepare Payload.");


capital P-repare (to match Proposal above)

rain-on · 2019-01-24T09:22:15Z

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

    actionOrBufferMessage(
        signedPayload, currentRound::handlePrepareMessage, RoundState::addPrepareMessage);
  }

  public void handleCommitPayload(final SignedData<CommitPayload> payload) {
-    LOG.info("Received a commit Payload.");
+    LOG.debug("Received a commit Payload.");


capital C-ommit

rain-on · 2019-01-24T09:23:05Z

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

@@ -191,7 +196,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.info("Received RoundChange Payload for a prior round. targetRound={}", targetRound);


this is probably trace - i.e. we really don't care too much about this.

I think more debug than trace. could be useful for troubleshooting issues. changing to debug.

rain-on · 2019-01-24T09:28:10Z

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

@@ -189,7 +201,7 @@ private boolean updateStateWithProposedBlock(final SignedData<ProposalPayload> m
    if (blockAccepted) {
      // There are times handling a proposed block is enough to enter prepared.
      if (wasPrepared != roundState.isPrepared()) {
-        LOG.info("Sending commit message.");
+        LOG.info("Sending commit message. round={}", roundState.getRoundIdentifier());


rain-on · 2019-01-24T09:28:27Z

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

@@ -212,7 +224,7 @@ private void peerIsPrepared(final SignedData<PreparePayload> msg) {
    final boolean wasPrepared = roundState.isPrepared();
    roundState.addPrepareMessage(msg);
    if (wasPrepared != roundState.isPrepared()) {
-      LOG.info("Sending commit message.");
+      LOG.info("Sending commit message. round={}", roundState.getRoundIdentifier());


debug? (maybe trace ...)

rain-on · 2019-01-24T09:29:26Z

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

@@ -97,7 +97,7 @@ public RoundChangeManager(
      final SignedData<RoundChangePayload> msg) {

    if (!isMessageValid(msg)) {
-      LOG.info("RoundChange message was invalid.");
+      LOG.error("RoundChange message was invalid.");


probably not an error ... just can't use the message (typically pantheon treats malformed packets as bad, but not terrible, as there are so many actors out there ... its kinda normal)

if its normal i'll make it info level.

rain-on · 2019-01-24T09:30:55Z

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

-    prepared =
-        (preparePayloads.size() >= prepareMessageCountForQuorum(quorum))
-            && proposalMessage.isPresent();
+    final long prepareQuorum = prepareMessageCountForQuorum(quorum);


this should get moved into the class constructor (i.e. can be calculated at startup).

rain-on · 2019-01-24T09:31:46Z

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

@@ -79,13 +82,15 @@ public boolean setProposedBlock(final SignedData<ProposalPayload> msg) {
  public void addPrepareMessage(final SignedData<PreparePayload> msg) {
    if (!proposalMessage.isPresent() || validator.validatePrepareMessage(msg)) {


re-reading this conditional kinda hurt my head, its correct, but not obviously.
May be a symptom of the design rather than the code ... but ... :/
Rather see it say "If(Proposal.isPresent() && isValid) store; else if(!Proposal) store.

jframe · 2019-01-24T10:46:54Z

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

@@ -75,6 +75,11 @@ 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={} messageData={} recipients={}",


it will be difficult to deconstruct, I was considering leaving it out. thinking about it more I don't think it is useful especially since the raw packet is already logged by netty.

jframe · 2019-01-24T10:56:27Z

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

@@ -84,7 +89,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={}",


I think we do want to know when we gain/remove validators. I've just added additional details to the existing log so we know who peer got disconnected.

jframe · 2019-01-24T10:57:41Z

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

    actionOrBufferMessage(
        signedPayload, currentRound::handleProposalMessage, RoundState::setProposedBlock);
  }

  public void handlePreparePayload(final SignedData<PreparePayload> signedPayload) {
-    LOG.info("Received a prepare Payload.");
+    LOG.debug("Received a prepare Payload.");


jframe · 2019-01-24T10:57:45Z

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

    actionOrBufferMessage(
        signedPayload, currentRound::handlePrepareMessage, RoundState::addPrepareMessage);
  }

  public void handleCommitPayload(final SignedData<CommitPayload> payload) {
-    LOG.info("Received a commit Payload.");
+    LOG.debug("Received a commit Payload.");


jframe · 2019-01-24T10:58:36Z

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

@@ -191,7 +196,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.info("Received RoundChange Payload for a prior round. targetRound={}", targetRound);


I think more debug than trace. could be useful for troubleshooting issues. changing to debug.

jframe · 2019-01-24T11:02:49Z

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

@@ -99,11 +104,13 @@ public void startRoundWith(

    SignedData<ProposalPayload> proposal;
    if (!latestCertificate.isPresent()) {
-      LOG.info("Multicasting NewRound with new block.");
+      LOG.info("Multicasting NewRound with new block. round={}", roundState.getRoundIdentifier());


agree with that. done.

jframe · 2019-01-24T11:03:12Z

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

      final Block block = blockCreator.createBlock(headerTimestamp);
      proposal = messageFactory.createSignedProposalPayload(getRoundIdentifier(), block);
    } else {
-      LOG.info("Multicasting NewRound from PreparedCertificate.");
+      LOG.info(


i'll make this trace too

jframe · 2019-01-24T11:05:06Z

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

@@ -132,14 +139,19 @@ public void startRoundWith(
                    blockHeader, extraDataToPublish));
    final BlockHeader newHeader = headerBuilder.buildBlockHeader();
    final Block newBlock = new Block(newHeader, block.getBody());
+    LOG.debug(
+        "Created proposal from prepared certificate blockHeader={} extraData={}",


nice catch. I was going to include the block number as well. don't think it's needed as this is included in the block header.
done.

jframe · 2019-01-24T11:07:05Z

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

@@ -169,12 +181,12 @@ private void actionReceivedProposal(final SignedData<ProposalPayload> msg) {
  }

  public void handlePrepareMessage(final SignedData<PreparePayload> msg) {
-    LOG.info("Received a prepare message.");
+    LOG.info("Received a prepare message. round={}", roundState.getRoundIdentifier());


not sure on these. might belong at debug level. is this and the handle logs useful for debugging or is a bit over the top?

jframe · 2019-01-24T11:09:56Z

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

@@ -97,7 +97,7 @@ public RoundChangeManager(
      final SignedData<RoundChangePayload> msg) {

    if (!isMessageValid(msg)) {
-      LOG.info("RoundChange message was invalid.");
+      LOG.error("RoundChange message was invalid.");


if its normal i'll make it info level.

jframe added 9 commits January 22, 2019 11:19

log chain height and event height details in ibft controller

7d2e48f

log chain height and event height details in ibft controller - includ…

d05236b

…e message type

more ibft logging

181b082

round state logging & spotless

6913c4b

add toString on IbftExtraData

13f9d2a

log extraData

9acacf3

log incoming ibft payloads

ea3d618

log processor shutdown

412e381

trace level logs for ibft rpc requests

29befdf

jframe requested review from rain-on and CjHare January 24, 2019 05:14

CjHare approved these changes Jan 24, 2019

View reviewed changes

rain-on reviewed Jan 24, 2019

View reviewed changes

PR changes

8bf81a4

jframe commented Jan 24, 2019

View reviewed changes

jframe added 3 commits January 24, 2019 21:17

typo

577346c

PR changes

de449fe

Merge branch 'master' into ibft_logging

b1d957d

jframe merged commit 752bfd6 into PegaSysEng:master Jan 25, 2019

jframe deleted the ibft_logging branch January 25, 2019 06:21

rain-on pushed a commit to rain-on/pantheon that referenced this pull request Jan 29, 2019

Additional logging details for IBFT (PegaSysEng#650)

eb71f3e

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Additional logging details for IBFT #650

Additional logging details for IBFT #650

jframe commented Jan 24, 2019

CjHare left a comment

rain-on Jan 24, 2019

jframe Jan 24, 2019

rain-on Jan 24, 2019

jframe Jan 24, 2019

rain-on Jan 26, 2019

rain-on Jan 24, 2019

jframe Jan 24, 2019

rain-on Jan 24, 2019

jframe Jan 24, 2019

rain-on Jan 24, 2019

jframe Jan 24, 2019

rain-on Jan 24, 2019

rain-on Jan 24, 2019

rain-on Jan 24, 2019

jframe Jan 24, 2019

rain-on Jan 24, 2019

rain-on Jan 24, 2019

jframe Jan 24, 2019

jframe Jan 24, 2019

jframe Jan 24, 2019

jframe Jan 24, 2019

jframe Jan 24, 2019

jframe Jan 24, 2019

jframe Jan 24, 2019

jframe Jan 24, 2019

jframe Jan 24, 2019

jframe Jan 24, 2019

		@@ -79,13 +82,15 @@ public boolean setProposedBlock(final SignedData<ProposalPayload> msg) {
		public void addPrepareMessage(final SignedData<PreparePayload> msg) {
		if (!proposalMessage.isPresent() \|\| validator.validatePrepareMessage(msg)) {

Additional logging details for IBFT #650

Additional logging details for IBFT #650

Conversation

jframe commented Jan 24, 2019

PR description

Fixed Issue(s)

CjHare left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment