From e139860549b0b1589c4aa64a29b0005b75b38487 Mon Sep 17 00:00:00 2001
From: garyschulte <garyschulte@gmail.com>
Date: Wed, 20 Jul 2022 11:18:33 -0700
Subject: [PATCH] logging additions for better engine visibility (#4136)

Signed-off-by: garyschulte <garyschulte@gmail.com>
---
 .../engine/EngineForkchoiceUpdated.java       | 29 +++++++++++++------
 .../methods/engine/EngineNewPayload.java      |  6 ++++
 2 files changed, 26 insertions(+), 9 deletions(-)

diff --git a/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineForkchoiceUpdated.java b/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineForkchoiceUpdated.java
index e5906ae53c..6ec375dc8c 100644
--- a/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineForkchoiceUpdated.java
+++ b/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineForkchoiceUpdated.java
@@ -77,10 +77,11 @@ public class EngineForkchoiceUpdated extends ExecutionEngineJsonRpcMethod {
         forkChoice.getHeadBlockHash(), maybeFinalizedHash, forkChoice.getSafeBlockHash());
 
     if (mergeContext.isSyncing()) {
-      return syncingResponse(requestId);
+      return syncingResponse(requestId, forkChoice);
     }
 
     if (mergeCoordinator.isBadBlock(forkChoice.getHeadBlockHash())) {
+      logForkchoiceUpdatedCall(INVALID, forkChoice);
       return new JsonRpcSuccessResponse(
           requestId,
           new EngineUpdateForkchoiceResult(
@@ -96,25 +97,21 @@ public class EngineForkchoiceUpdated extends ExecutionEngineJsonRpcMethod {
         mergeCoordinator.getOrSyncHeaderByHash(forkChoice.getHeadBlockHash());
 
     if (newHead.isEmpty()) {
-      return syncingResponse(requestId);
+      return syncingResponse(requestId, forkChoice);
     }
 
-    LOG.info(
-        "Consensus fork-choice-update: head: {}, finalized: {}, safeBlockHash: {}",
-        forkChoice.getHeadBlockHash(),
-        forkChoice.getFinalizedBlockHash(),
-        forkChoice.getSafeBlockHash());
-
     maybePayloadAttributes.ifPresentOrElse(
         this::logPayload, () -> LOG.debug("Payload attributes are null"));
 
     if (!isValidForkchoiceState(
         forkChoice.getSafeBlockHash(), forkChoice.getFinalizedBlockHash(), newHead.get())) {
+      logForkchoiceUpdatedCall(INVALID, forkChoice);
       return new JsonRpcErrorResponse(requestId, JsonRpcError.INVALID_FORKCHOICE_STATE);
     }
 
     // TODO: post-merge cleanup, this should be unnecessary after merge
     if (!mergeCoordinator.latestValidAncestorDescendsFromTerminal(newHead.get())) {
+      logForkchoiceUpdatedCall(INVALID, forkChoice);
       return new JsonRpcSuccessResponse(
           requestId,
           new EngineUpdateForkchoiceResult(
@@ -137,6 +134,7 @@ public class EngineForkchoiceUpdated extends ExecutionEngineJsonRpcMethod {
                         payloadAttributes.getSuggestedFeeRecipient())));
 
     if (!result.isValid()) {
+      logForkchoiceUpdatedCall(INVALID, forkChoice);
       return handleNonValidForkchoiceUpdate(requestId, result);
     }
 
@@ -158,6 +156,7 @@ public class EngineForkchoiceUpdated extends ExecutionEngineJsonRpcMethod {
                 pid::toHexString,
                 () -> maybePayloadAttributes.map(EnginePayloadAttributesParameter::serialize)));
 
+    logForkchoiceUpdatedCall(VALID, forkChoice);
     return new JsonRpcSuccessResponse(
         requestId,
         new EngineUpdateForkchoiceResult(
@@ -256,8 +255,20 @@ public class EngineForkchoiceUpdated extends ExecutionEngineJsonRpcMethod {
     return mergeCoordinator.isDescendantOf(maybeSafeBlock.get(), newBlock);
   }
 
-  private JsonRpcResponse syncingResponse(final Object requestId) {
+  private JsonRpcResponse syncingResponse(
+      final Object requestId, final EngineForkchoiceUpdatedParameter forkChoice) {
+    logForkchoiceUpdatedCall(SYNCING, forkChoice);
     return new JsonRpcSuccessResponse(
         requestId, new EngineUpdateForkchoiceResult(SYNCING, null, null, Optional.empty()));
   }
+
+  private void logForkchoiceUpdatedCall(
+      final EngineStatus status, final EngineForkchoiceUpdatedParameter forkChoice) {
+    LOG.info(
+        "{} for fork-choice-update: head: {}, finalized: {}, safeBlockHash: {}",
+        status.name(),
+        forkChoice.getHeadBlockHash(),
+        forkChoice.getFinalizedBlockHash(),
+        forkChoice.getSafeBlockHash());
+  }
 }
diff --git a/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineNewPayload.java b/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineNewPayload.java
index dc1002a769..0a6e4b0f2b 100644
--- a/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineNewPayload.java
+++ b/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineNewPayload.java
@@ -165,6 +165,11 @@ public class EngineNewPayload extends ExecutionEngineJsonRpcMethod {
         new Block(newBlockHeader, new BlockBody(transactions, Collections.emptyList()));
 
     if (mergeContext.isSyncing() || parentHeader.isEmpty()) {
+      LOG.info(
+          "isSyncing: {} parentHeaderMissing: {}, adding {} to backwardsync",
+          mergeContext.isSyncing(),
+          parentHeader.isEmpty(),
+          block.getHash());
       mergeCoordinator
           .appendNewPayloadToSync(block)
           .exceptionally(
@@ -177,6 +182,7 @@ public class EngineNewPayload extends ExecutionEngineJsonRpcMethod {
 
     // TODO: post-merge cleanup
     if (!mergeCoordinator.latestValidAncestorDescendsFromTerminal(newBlockHeader)) {
+      LOG.warn("payload did not descend from terminal: {}", newBlockHeader.toLogString());
       mergeCoordinator.addBadBlock(block);
       return respondWithInvalid(
           reqId,