Improve UX of initial sync logs, pushing not relevant logs to debug l…

CHANGELOG.md

@@ -4,6 +4,7 @@
 
 ### Additions and Improvements
 - Bring GraphQL into compliance with execution-api specs [#4112](https://github.com/hyperledger/besu/pull/4112)
+- Improve UX of initial sync logs, pushing not relevant logs to debug level [#4486](https://github.com/hyperledger/besu/pull/4486)
 
 ### Bug Fixes
 

ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineForkchoiceUpdated.java

@@ -38,6 +38,7 @@
 import org.hyperledger.besu.ethereum.core.BlockHeader;
 
 import java.util.Optional;
+import java.util.function.BiConsumer;
 
 import io.vertx.core.Vertx;
 import org.slf4j.Logger;
@@ -265,25 +266,49 @@ private boolean isValidForkchoiceState(
   private JsonRpcResponse syncingResponse(
       final Object requestId, final EngineForkchoiceUpdatedParameter forkChoice) {
 
-    logForkchoiceUpdatedCall(SYNCING, forkChoice);
+    logForkchoiceUpdatedCall(this::logAtDebug, 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 static final String logMessage =
+      "{} for fork-choice-update: head: {}, finalized: {}, safeBlockHash: {}";
 
   private void logForkchoiceUpdatedCall(
       final EngineStatus status, final EngineForkchoiceUpdatedParameter forkChoice) {
+    logForkchoiceUpdatedCall(this::logAtInfo, status, forkChoice);
+  }
+
+  private void logForkchoiceUpdatedCall(
+      final BiConsumer<EngineStatus, EngineForkchoiceUpdatedParameter> logAtLevel,
+      final EngineStatus status,
+      final EngineForkchoiceUpdatedParameter forkChoice) {
     // 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());
+      logAtLevel.accept(status, forkChoice);
     }
   }
+
+  private void logAtInfo(
+      final EngineStatus status, final EngineForkchoiceUpdatedParameter forkChoice) {
+    LOG.info(
+        logMessage,
+        status.name(),
+        forkChoice.getHeadBlockHash(),
+        forkChoice.getFinalizedBlockHash(),
+        forkChoice.getSafeBlockHash());
+  }
+
+  private void logAtDebug(
+      final EngineStatus status, final EngineForkchoiceUpdatedParameter forkChoice) {
+    LOG.debug(
+        logMessage,
+        status.name(),
+        forkChoice.getHeadBlockHash(),
+        forkChoice.getFinalizedBlockHash(),
+        forkChoice.getSafeBlockHash());
+  }
 }

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardsSyncAlgorithm.java

@@ -131,10 +131,10 @@ protected CompletableFuture<Void> waitForReady() {
   private void checkReadiness(final CountDownLatch latch, final long idTTD, final long idIS) {
     try {
       if (!context.isReady()) {
-        LOG.info("Waiting for preconditions...");
+        LOG.debug("Waiting for preconditions...");
         final boolean await = latch.await(2, TimeUnit.MINUTES);
         if (await) {
-          LOG.info("Preconditions meet...");
+          LOG.debug("Preconditions meet...");
         }
       }
     } catch (InterruptedException e) {

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/fastsync/FastSyncDownloader.java

@@ -76,15 +76,16 @@ public CompletableFuture<FastSyncState> start() {
     if (!running.compareAndSet(false, true)) {
       throw new IllegalStateException("FastSyncDownloader already running");
     }
+    LOG.info("Starting sync");
     return start(initialFastSyncState);
   }
 
   protected CompletableFuture<FastSyncState> start(final FastSyncState fastSyncState) {
-    LOG.info("Starting sync.");
     if (worldStateStorage instanceof BonsaiWorldStateKeyValueStorage) {
       LOG.info("Clearing bonsai flat account db");
       worldStateStorage.clearFlatDatabase();
     }
+    LOG.debug("Start sync with initial sync state {}", fastSyncState);
     return findPivotBlock(fastSyncState, fss -> downloadChainAndWorldState(fastSyncActions, fss));
   }
 
@@ -108,7 +109,7 @@ protected CompletableFuture<FastSyncState> handleFailure(final Throwable error)
     if (rootCause instanceof FastSyncException) {
       return CompletableFuture.failedFuture(error);
     } else if (rootCause instanceof StalledDownloadException) {
-      LOG.info("Re-pivoting to newer block.");
+      LOG.debug("Stalled sync re-pivoting to newer block.");
       return start(FastSyncState.EMPTY_SYNC_STATE);
     } else if (rootCause instanceof CancellationException) {
       return CompletableFuture.failedFuture(error);

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/fastsync/FastSyncTargetManager.java

@@ -68,7 +68,7 @@ protected CompletableFuture<Optional<EthPeer>> selectBestAvailableSyncTarget() {
     final BlockHeader pivotBlockHeader = fastSyncState.getPivotBlockHeader().get();
     final Optional<EthPeer> maybeBestPeer = ethContext.getEthPeers().bestPeerWithHeightEstimate();
     if (!maybeBestPeer.isPresent()) {
-      LOG.info(
+      LOG.debug(
           "No sync target, checking current peers for usefulness: {}",
           ethContext.getEthPeers().peerCount());
       return completedFuture(Optional.empty());