logging additions for better engine visibility (#4136)

Signed-off-by: garyschulte <garyschulte@gmail.com>

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

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,