limit engine-api info logging (hyperledger#4156)

* limit engine-api info logging * use a common constant for engine api logging threshold Signed-off-by: garyschulte <garyschulte@gmail.com>
noirgif · Jul 26, 2022 · eabbea6 · eabbea6
1 parent 01d077b
commit eabbea6
Show file tree

Hide file tree

Showing 3 changed files with 34 additions and 20 deletions.
diff --git a/.../hyperledger/besu/ethereum/api/jsonrpc/internal/methods/ExecutionEngineJsonRpcMethod.java b/.../hyperledger/besu/ethereum/api/jsonrpc/internal/methods/ExecutionEngineJsonRpcMethod.java
@@ -37,6 +37,7 @@ public enum EngineStatus {
     INVALID_BLOCK_HASH;
   }
 
+  public static final long ENGINE_API_LOGGING_THRESHOLD = 60000L;
   private final Vertx syncVertx;
   private static final Logger LOG = LoggerFactory.getLogger(ExecutionEngineJsonRpcMethod.class);
   protected final MergeContext mergeContext;

diff --git a/...yperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineForkchoiceUpdated.java b/...yperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineForkchoiceUpdated.java
@@ -257,18 +257,26 @@ private boolean isValidForkchoiceState(
 
   private JsonRpcResponse syncingResponse(
       final Object requestId, final EngineForkchoiceUpdatedParameter forkChoice) {
+
     logForkchoiceUpdatedCall(SYNCING, forkChoice);
     return new JsonRpcSuccessResponse(
         requestId, new EngineUpdateForkchoiceResult(SYNCING, null, null, Optional.empty()));
   }
 
+  // fcU calls are synchronous, no need to make volatile
+  private long lastFcuInfoLog = System.currentTimeMillis();
+
   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());
+    // cheaply limit the noise of fcU during consensus client syncing to once a minute:
+    if (lastFcuInfoLog + ENGINE_API_LOGGING_THRESHOLD < System.currentTimeMillis()) {
+      lastFcuInfoLog = System.currentTimeMillis();
+      LOG.info(
+          "{} for fork-choice-update: head: {}, finalized: {}, safeBlockHash: {}",
+          status.name(),
+          forkChoice.getHeadBlockHash(),
+          forkChoice.getFinalizedBlockHash(),
+          forkChoice.getSafeBlockHash());
+    }
   }
 }
diff --git a/...a/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineNewPayload.java b/...a/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineNewPayload.java
@@ -19,8 +19,9 @@
 import static org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.EngineStatus.INVALID_BLOCK_HASH;
 import static org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.EngineStatus.SYNCING;
 import static org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.EngineStatus.VALID;
-import static org.hyperledger.besu.util.Slf4jLambdaHelper.infoLambda;
+import static org.hyperledger.besu.util.Slf4jLambdaHelper.debugLambda;
 import static org.hyperledger.besu.util.Slf4jLambdaHelper.traceLambda;
+import static org.hyperledger.besu.util.Slf4jLambdaHelper.warnLambda;
 
 import org.hyperledger.besu.consensus.merge.blockcreation.MergeMiningCoordinator;
 import org.hyperledger.besu.datatypes.Hash;
@@ -155,7 +156,6 @@ public JsonRpcResponse syncResponse(final JsonRpcRequestContext requestContext)
         protocolContext.getBlockchain().getBlockHeader(blockParam.getParentHash());
     if (parentHeader.isPresent()
         && (blockParam.getTimestamp() <= parentHeader.get().getTimestamp())) {
-      LOG.info("method parameter timestamp not greater than parent");
       return respondWithInvalid(
           reqId,
           blockParam,
@@ -167,7 +167,7 @@ public JsonRpcResponse syncResponse(final JsonRpcRequestContext requestContext)
         new Block(newBlockHeader, new BlockBody(transactions, Collections.emptyList()));
 
     if (mergeContext.isSyncing() || parentHeader.isEmpty()) {
-      LOG.info(
+      LOG.debug(
           "isSyncing: {} parentHeaderMissing: {}, adding {} to backwardsync",
           mergeContext.isSyncing(),
           parentHeader.isEmpty(),
@@ -185,7 +185,6 @@ public JsonRpcResponse syncResponse(final JsonRpcRequestContext requestContext)
 
     // TODO: post-merge cleanup
     if (!mergeCoordinator.latestValidAncestorDescendsFromTerminal(newBlockHeader)) {
-      LOG.warn("payload did not descend from terminal: {}", newBlockHeader.toLogString());
       mergeCoordinator.addBadBlock(block);
       return respondWithInvalid(
           reqId,
@@ -217,7 +216,7 @@ JsonRpcResponse respondWith(
       final EnginePayloadParameter param,
       final Hash latestValidHash,
       final EngineStatus status) {
-    infoLambda(
+    debugLambda(
         LOG,
         "New payload: number: {}, hash: {}, parentHash: {}, latestValidHash: {}, status: {}",
         () -> param.getBlockNumber(),
@@ -229,20 +228,26 @@ JsonRpcResponse respondWith(
         requestId, new EnginePayloadStatusResult(status, latestValidHash, Optional.empty()));
   }
 
+  // engine api calls are synchronous, no need for volatile
+  private long lastInvalidWarn = System.currentTimeMillis();
+
   JsonRpcResponse respondWithInvalid(
       final Object requestId,
       final EnginePayloadParameter param,
       final Hash latestValidHash,
       final String validationError) {
-    infoLambda(
-        LOG,
-        "Invalid new payload: number: {}, hash: {}, parentHash: {}, latestValidHash: {}, status: {}, validationError: {}",
-        () -> param.getBlockNumber(),
-        () -> param.getBlockHash(),
-        () -> param.getParentHash(),
-        () -> latestValidHash == null ? null : latestValidHash.toHexString(),
-        INVALID::name,
-        () -> validationError);
+    if (lastInvalidWarn + ENGINE_API_LOGGING_THRESHOLD < System.currentTimeMillis()) {
+      lastInvalidWarn = System.currentTimeMillis();
+      warnLambda(
+          LOG,
+          "Invalid new payload: number: {}, hash: {}, parentHash: {}, latestValidHash: {}, status: {}, validationError: {}",
+          () -> param.getBlockNumber(),
+          () -> param.getBlockHash(),
+          () -> param.getParentHash(),
+          () -> latestValidHash == null ? null : latestValidHash.toHexString(),
+          INVALID::name,
+          () -> validationError);
+    }
     return new JsonRpcSuccessResponse(
         requestId,
         new EnginePayloadStatusResult(INVALID, latestValidHash, Optional.of(validationError)));