Fix log in case of sync failures

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>
hyperledger · Nov 12, 2022 · 0ad7d31 · 0ad7d31
1 parent 00a5468
commit 0ad7d31
Show file tree

Hide file tree

Showing 5 changed files with 25 additions and 11 deletions.
diff --git a/...ge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java b/...ge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java
@@ -390,7 +390,11 @@ public Optional<BlockHeader> getOrSyncHeaderByHash(
   }
 
   private Void logSyncException(final Hash blockHash, final Throwable exception) {
-    LOG.warn("Sync to block hash " + blockHash.toHexString() + " failed", exception.getMessage());
+    debugLambda(
+        LOG,
+        "Sync to block hash {} failed, reason {}",
+        blockHash::toHexString,
+        exception::getMessage);
     return null;
   }
 

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
@@ -180,7 +180,6 @@ public JsonRpcResponse syncResponse(final JsonRpcRequestContext requestContext)
 
     final var block =
         new Block(newBlockHeader, new BlockBody(transactions, Collections.emptyList()));
-    final String warningMessage = "Sync to block " + block.toLogString() + " failed";
 
     if (mergeContext.get().isSyncing() || parentHeader.isEmpty()) {
       LOG.debug(
@@ -192,7 +191,11 @@ public JsonRpcResponse syncResponse(final JsonRpcRequestContext requestContext)
           .appendNewPayloadToSync(block)
           .exceptionally(
               exception -> {
-                LOG.warn(warningMessage, exception.getMessage());
+                debugLambda(
+                    LOG,
+                    "Sync to block {} failed, reason {}",
+                    block::toLogString,
+                    exception::getMessage);
                 return null;
               });
       return respondWith(reqId, blockParam, null, SYNCING);

diff --git a/...rc/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java b/...rc/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java
@@ -131,6 +131,7 @@ public synchronized CompletableFuture<Void> syncBackwardsUntil(final Hash newBlo
     backwardChain.addNewHash(newBlockHash);
     return maybeFuture.orElseGet(
         () -> {
+          LOG.info("Starting a new backward sync session");
           Status status = new Status(prepareBackwardSyncFutureWithRetry());
           this.currentBackwardSyncStatus.set(status);
           return status.currentFuture;
@@ -147,7 +148,12 @@ public synchronized CompletableFuture<Void> syncBackwardsUntil(final Block newPi
     backwardChain.appendTrustedBlock(newPivot);
     return maybeFuture.orElseGet(
         () -> {
+          LOG.info("Starting a new backward sync session");
+          LOG.info("Backward sync target block is {}", newPivot.toLogString());
           Status status = new Status(prepareBackwardSyncFutureWithRetry());
+          status.setSyncRange(
+              protocolContext.getBlockchain().getChainHeadBlockNumber(),
+              newPivot.getHeader().getNumber());
           this.currentBackwardSyncStatus.set(status);
           return status.currentFuture;
         });
@@ -170,6 +176,7 @@ private CompletableFuture<Void> prepareBackwardSyncFutureWithRetry() {
             (unused, throwable) -> {
               this.currentBackwardSyncStatus.set(null);
               if (throwable != null) {
+                LOG.info("Current backward sync session failed, it will be restarted");
                 throw extractBackwardSyncException(throwable)
                     .orElse(new BackwardSyncException(throwable));
               }
@@ -407,9 +414,5 @@ public long getTargetChainHeight() {
     public long getInitialChainHeight() {
       return initialChainHeight;
     }
-
-    public long getBlockCount() {
-      return targetChainHeight - initialChainHeight;
-    }
   }
 }
diff --git a/...h/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java b/...h/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java
@@ -116,7 +116,7 @@ private void logProgress(final long currLowestDownloadedHeight) {
 
     final float completedPercentage = 100.0f * downloaded / estimatedTotal;
 
-    if (currLowestDownloadedHeight > initialHeight) {
+    if (completedPercentage < 100.0f) {
       final long now = System.currentTimeMillis();
       if (now - lastLogAt > MILLIS_DELAY_BETWEEN_PROGRESS_LOG) {
         LOG.info(

diff --git a/...th/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java b/...th/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java
@@ -93,6 +93,9 @@ protected Void saveBlocks(final List<Block> blocks) {
       return null;
     }
 
+    long lastImportedHeight =
+        context.getProtocolContext().getBlockchain().getChainHeadBlockNumber();
+
     for (Block block : blocks) {
       final Optional<Block> parent =
           context
@@ -108,14 +111,15 @@ protected Void saveBlocks(final List<Block> blocks) {
             block.getHeader().getParentHash()::toString,
             block::toLogString,
             context::getBatchSize);
-        logProgress(blocks.get(blocks.size() - 1).getHeader().getNumber());
+        logProgress(lastImportedHeight);
         return null;
       } else {
         context.saveBlock(block);
+        lastImportedHeight = block.getHeader().getNumber();
       }
     }
 
-    logProgress(blocks.get(blocks.size() - 1).getHeader().getNumber());
+    logProgress(lastImportedHeight);
 
     context.resetBatchSize();
     return null;
@@ -129,7 +133,7 @@ private void logProgress(final long currImportedHeight) {
 
     final float completedPercentage = 100.0f * imported / estimatedTotal;
 
-    if (currImportedHeight < targetHeight) {
+    if (completedPercentage < 100.0f) {
       final long now = System.currentTimeMillis();
       if (now - lastLogAt > MILLIS_DELAY_BETWEEN_PROGRESS_LOG) {
         LOG.info(