Backward sync log UX improvements

CHANGELOG.md

@@ -8,6 +8,7 @@
 - Explain and improve price validation for London and local transactions during block proposal selection [#4602](https://github.com/hyperledger/besu/pull/4602)
 - Support for ephemeral testnet Shandong.  EIPs are still in flux, besu does not fully sync yet, and the network is subject to restarts. [#//FIXME](https://github.com/hyperledger/besu/pull///FIXME)
 - Improve performance of block processing by parallelizing some parts during the "commit" step [#4635](https://github.com/hyperledger/besu/pull/4635)
+- Backward sync log UX improvements [#4655](https://github.com/hyperledger/besu/pull/4655)
 
 ### Bug Fixes
 

consensus/merge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java

@@ -439,7 +439,7 @@ public ForkchoiceResult updateForkChoice(
 
     if (newHead.getNumber() < blockchain.getChainHeadBlockNumber()
         && isDescendantOf(newHead, blockchain.getChainHeadHeader())) {
-      LOG.info("Ignoring update to old head");
+      debugLambda(LOG, "Ignoring update to old head {}", newHead::toLogString);
       return ForkchoiceResult.withIgnoreUpdateToOldHead(newHead);
     }
 

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/RetryingGetBlockFromPeersTask.java

@@ -102,8 +102,11 @@ protected void handleTaskError(final Throwable error) {
           this::getAssignedPeer,
           this::getRetryCount);
     } else {
-      LOG.warn(
-          "Failed to get block {} after {} retries", logBlockNumberMaybeHash(), getRetryCount());
+      debugLambda(
+          LOG,
+          "Failed to get block {} after {} retries",
+          this::logBlockNumberMaybeHash,
+          this::getRetryCount);
     }
     super.handleTaskError(error);
   }

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

@@ -55,9 +55,7 @@ public class BackwardSyncContext {
   private final EthContext ethContext;
   private final MetricsSystem metricsSystem;
   private final SyncState syncState;
-
-  private final AtomicReference<CompletableFuture<Void>> currentBackwardSyncFuture =
-      new AtomicReference<>();
+  private final AtomicReference<Status> currentBackwardSyncStatus = new AtomicReference<>();
   private final BackwardChain backwardChain;
   private int batchSize = BATCH_SIZE;
   private Optional<Hash> maybeFinalized = Optional.empty();
@@ -105,8 +103,8 @@ public BackwardSyncContext(
   }
 
   public synchronized boolean isSyncing() {
-    return Optional.ofNullable(currentBackwardSyncFuture.get())
-        .map(CompletableFuture::isDone)
+    return Optional.ofNullable(currentBackwardSyncStatus.get())
+        .map(status -> status.currentFuture.isDone())
         .orElse(Boolean.FALSE);
   }
 
@@ -125,31 +123,33 @@ public synchronized void updateHeads(final Hash head, final Hash finalizedBlockH
 
   public synchronized CompletableFuture<Void> syncBackwardsUntil(final Hash newBlockHash) {
     Optional<CompletableFuture<Void>> maybeFuture =
-        Optional.ofNullable(this.currentBackwardSyncFuture.get());
+        Optional.ofNullable(this.currentBackwardSyncStatus.get())
+            .map(status -> status.currentFuture);
     if (isTrusted(newBlockHash)) {
       return maybeFuture.orElseGet(() -> CompletableFuture.completedFuture(null));
     }
     backwardChain.addNewHash(newBlockHash);
     return maybeFuture.orElseGet(
         () -> {
-          CompletableFuture<Void> future = prepareBackwardSyncFutureWithRetry();
-          this.currentBackwardSyncFuture.set(future);
-          return future;
+          Status status = new Status(prepareBackwardSyncFutureWithRetry());
+          this.currentBackwardSyncStatus.set(status);
+          return status.currentFuture;
         });
   }
 
   public synchronized CompletableFuture<Void> syncBackwardsUntil(final Block newPivot) {
     Optional<CompletableFuture<Void>> maybeFuture =
-        Optional.ofNullable(this.currentBackwardSyncFuture.get());
+        Optional.ofNullable(this.currentBackwardSyncStatus.get())
+            .map(status -> status.currentFuture);
     if (isTrusted(newPivot.getHash())) {
       return maybeFuture.orElseGet(() -> CompletableFuture.completedFuture(null));
     }
     backwardChain.appendTrustedBlock(newPivot);
     return maybeFuture.orElseGet(
         () -> {
-          CompletableFuture<Void> future = prepareBackwardSyncFutureWithRetry();
-          this.currentBackwardSyncFuture.set(future);
-          return future;
+          Status status = new Status(prepareBackwardSyncFutureWithRetry());
+          this.currentBackwardSyncStatus.set(status);
+          return status.currentFuture;
         });
   }
 
@@ -168,7 +168,7 @@ private CompletableFuture<Void> prepareBackwardSyncFutureWithRetry() {
     return prepareBackwardSyncFutureWithRetry(maxRetries)
         .handle(
             (unused, throwable) -> {
-              this.currentBackwardSyncFuture.set(null);
+              this.currentBackwardSyncStatus.set(null);
               if (throwable != null) {
                 throw extractBackwardSyncException(throwable)
                     .orElse(new BackwardSyncException(throwable));
@@ -201,8 +201,8 @@ protected void processException(final Throwable throwable) {
         .ifPresentOrElse(
             backwardSyncException -> {
               if (backwardSyncException.shouldRestart()) {
-                LOG.info(
-                    "Backward sync failed ({}). Current Peers: {}. Retrying in {} milliseconds...",
+                LOG.debug(
+                    "Backward sync failed ({}). Current Peers: {}. Retrying in {} milliseconds",
                     throwable.getMessage(),
                     ethContext.getEthPeers().peerCount(),
                     millisBetweenRetries);
@@ -213,8 +213,8 @@ protected void processException(final Throwable throwable) {
               }
             },
             () -> {
-              LOG.warn(
-                  "Backward sync failed ({}). Current Peers: {}. Retrying in {} milliseconds...",
+              LOG.debug(
+                  "Backward sync failed ({}). Current Peers: {}. Retrying in {} milliseconds",
                   throwable.getMessage(),
                   ethContext.getEthPeers().peerCount(),
                   millisBetweenRetries);
@@ -278,10 +278,6 @@ public boolean isReady() {
         && syncState.isInitialSyncPhaseDone();
   }
 
-  public CompletableFuture<Void> stop() {
-    return currentBackwardSyncFuture.get();
-  }
-
   public void subscribeBadChainListener(final BadChainListener badChainListener) {
     badChainListeners.subscribe(badChainListener);
   }
@@ -365,6 +361,10 @@ public Optional<Hash> findMaybeFinalized() {
         .findFirst();
   }
 
+  public Status getStatus() {
+    return currentBackwardSyncStatus.get();
+  }
+
   private void emitBadChainEvent(final Block badBlock) {
     final List<Block> badBlockDescendants = new ArrayList<>();
     final List<BlockHeader> badBlockHeaderDescendants = new ArrayList<>();
@@ -385,4 +385,31 @@ private void emitBadChainEvent(final Block badBlock) {
     badChainListeners.forEach(
         listener -> listener.onBadChain(badBlock, badBlockDescendants, badBlockHeaderDescendants));
   }
+
+  static class Status {
+    private final CompletableFuture<Void> currentFuture;
+    private long targetChainHeight;
+    private long initialChainHeight;
+
+    public Status(final CompletableFuture<Void> currentFuture) {
+      this.currentFuture = currentFuture;
+    }
+
+    public void setSyncRange(final long initialHeight, final long targetHeight) {
+      initialChainHeight = initialHeight;
+      targetChainHeight = targetHeight;
+    }
+
+    public long getTargetChainHeight() {
+      return targetChainHeight;
+    }
+
+    public long getInitialChainHeight() {
+      return initialChainHeight;
+    }
+
+    public long getBlockCount() {
+      return targetChainHeight - initialChainHeight;
+    }
+  }
 }

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

@@ -15,7 +15,6 @@
 package org.hyperledger.besu.ethereum.eth.sync.backwardsync;
 
 import static org.hyperledger.besu.util.Slf4jLambdaHelper.debugLambda;
-import static org.hyperledger.besu.util.Slf4jLambdaHelper.infoLambda;
 
 import org.hyperledger.besu.datatypes.Hash;
 import org.hyperledger.besu.ethereum.core.BlockHeader;
@@ -31,6 +30,8 @@
 
 public class BackwardSyncStep {
   private static final Logger LOG = LoggerFactory.getLogger(BackwardSyncStep.class);
+  private static final long MILLIS_DELAY_BETWEEN_PROGRESS_LOG = 10_000L;
+  private static long lastLogAt = 0;
   private final BackwardSyncContext context;
   private final BackwardChain backwardChain;
 
@@ -61,7 +62,7 @@ protected Hash possibleRestoreOldNodes(final BlockHeader firstAncestor) {
   @VisibleForTesting
   protected CompletableFuture<List<BlockHeader>> requestHeaders(final Hash hash) {
     final int batchSize = context.getBatchSize();
-    debugLambda(LOG, "Requesting header for hash {}", hash::toHexString);
+    LOG.debug("Requesting headers for hash {}, with batch size {}", hash, batchSize);
 
     final RetryingGetHeadersEndingAtFromPeerByHashTask
         retryingGetHeadersEndingAtFromPeerByHashTask =
@@ -101,12 +102,37 @@ protected Void saveHeaders(final List<BlockHeader> blockHeaders) {
     for (BlockHeader blockHeader : blockHeaders) {
       saveHeader(blockHeader);
     }
-    infoLambda(
-        LOG,
-        "Saved headers {} -> {} (head: {})",
-        () -> blockHeaders.get(0).getNumber(),
-        () -> blockHeaders.get(blockHeaders.size() - 1).getNumber(),
-        () -> context.getProtocolContext().getBlockchain().getChainHead().getHeight());
+
+    logProgress(blockHeaders.get(blockHeaders.size() - 1).getNumber());
+
     return null;
   }
+
+  private void logProgress(final long currLowestDownloadedHeight) {
+    final long targetHeight = context.getStatus().getTargetChainHeight();
+    final long initialHeight = context.getStatus().getInitialChainHeight();
+    final long estimatedTotal = targetHeight - initialHeight;
+    final long downloaded = targetHeight - currLowestDownloadedHeight;
+
+    final float completedPercentage = 100.0f * downloaded / estimatedTotal;
+
+    if (currLowestDownloadedHeight > initialHeight) {
+      final long now = System.currentTimeMillis();
+      if (now - lastLogAt > MILLIS_DELAY_BETWEEN_PROGRESS_LOG) {
+        LOG.info(
+            String.format(
+                "Backward sync phase 1 of 2, %.2f%% completed, downloaded %d headers of at least %d. Peers: %d",
+                completedPercentage,
+                downloaded,
+                estimatedTotal,
+                context.getEthContext().getEthPeers().peerCount()));
+        lastLogAt = now;
+      }
+    } else {
+      LOG.info(
+          String.format(
+              "Backward sync phase 1 of 2 completed, downloaded a total of %d headers. Peers: %d",
+              downloaded, context.getEthContext().getEthPeers().peerCount()));
+    }
+  }
 }

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

@@ -22,6 +22,7 @@
 
 import org.hyperledger.besu.datatypes.Hash;
 import org.hyperledger.besu.ethereum.chain.MutableBlockchain;
+import org.hyperledger.besu.ethereum.core.Block;
 import org.hyperledger.besu.ethereum.core.BlockHeader;
 
 import java.util.Optional;
@@ -57,11 +58,15 @@ public CompletableFuture<Void> pickNextStep() {
     final Optional<Hash> firstHash = context.getBackwardChain().getFirstHashToAppend();
     if (firstHash.isPresent()) {
       return executeSyncStep(firstHash.get())
-          .whenComplete(
-              (result, throwable) -> {
-                if (throwable == null) {
-                  context.getBackwardChain().removeFromHashToAppend(firstHash.get());
-                }
+          .thenAccept(
+              result -> {
+                LOG.info("Backward sync target block is {}", result.toLogString());
+                context.getBackwardChain().removeFromHashToAppend(firstHash.get());
+                context
+                    .getStatus()
+                    .setSyncRange(
+                        context.getProtocolContext().getBlockchain().getChainHeadBlockNumber(),
+                        result.getHeader().getNumber());
               });
     }
     if (!context.isReady()) {
@@ -73,7 +78,7 @@ public CompletableFuture<Void> pickNextStep() {
         context.getBackwardChain().getFirstAncestorHeader();
     if (possibleFirstAncestorHeader.isEmpty()) {
       this.finished = true;
-      LOG.info("The Backward sync is done...");
+      LOG.info("The Backward sync is done");
       context.getBackwardChain().clear();
       return CompletableFuture.completedFuture(null);
     }
@@ -85,13 +90,16 @@ public CompletableFuture<Void> pickNextStep() {
     if (blockchain.getChainHead().getHeight() > firstAncestorHeader.getNumber()) {
       debugLambda(
           LOG,
-          "Backward reached below previous head {} : {}",
+          "Backward reached below current chain head {} : {}",
           () -> blockchain.getChainHead().toLogString(),
           firstAncestorHeader::toLogString);
     }
 
     if (finalBlockConfirmation.ancestorHeaderReached(firstAncestorHeader)) {
-      LOG.info("Backward sync reached ancestor header, starting Forward sync");
+      debugLambda(
+          LOG,
+          "Backward sync reached ancestor header with {}, starting Forward sync",
+          firstAncestorHeader::toLogString);
       return executeForwardAsync();
     }
 
@@ -104,7 +112,7 @@ public CompletableFuture<Void> executeProcessKnownAncestors() {
   }
 
   @VisibleForTesting
-  public CompletableFuture<Void> executeSyncStep(final Hash hash) {
+  public CompletableFuture<Block> executeSyncStep(final Hash hash) {
     return new SyncStepStep(context, context.getBackwardChain()).executeAsync(hash);
   }