From b22d1a00f35dd52306870491350fa19708b2a375 Mon Sep 17 00:00:00 2001 From: Fabio Di Fabio Date: Fri, 11 Nov 2022 12:58:23 +0100 Subject: [PATCH 1/8] Backward sync log UX improvements Signed-off-by: Fabio Di Fabio --- .../merge/blockcreation/MergeCoordinator.java | 2 +- .../task/RetryingGetBlockFromPeersTask.java | 7 +- .../backwardsync/BackwardSyncContext.java | 71 +++++++++++++------ .../sync/backwardsync/BackwardSyncStep.java | 42 ++++++++--- .../backwardsync/BackwardsSyncAlgorithm.java | 26 ++++--- .../sync/backwardsync/ForwardSyncStep.java | 52 +++++++++++--- .../eth/sync/backwardsync/SyncStepStep.java | 11 +-- 7 files changed, 155 insertions(+), 56 deletions(-) diff --git a/consensus/merge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java b/consensus/merge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java index 4ca248546fa..438d294602c 100644 --- a/consensus/merge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java +++ b/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); } diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/RetryingGetBlockFromPeersTask.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/RetryingGetBlockFromPeersTask.java index c1894189065..7d5062ec74d 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/RetryingGetBlockFromPeersTask.java +++ b/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); } diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java index deb94063441..fb941722733 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java +++ b/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> currentBackwardSyncFuture = - new AtomicReference<>(); + private final AtomicReference currentBackwardSyncStatus = new AtomicReference<>(); private final BackwardChain backwardChain; private int batchSize = BATCH_SIZE; private Optional 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 syncBackwardsUntil(final Hash newBlockHash) { Optional> 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 future = prepareBackwardSyncFutureWithRetry(); - this.currentBackwardSyncFuture.set(future); - return future; + Status status = new Status(prepareBackwardSyncFutureWithRetry()); + this.currentBackwardSyncStatus.set(status); + return status.currentFuture; }); } public synchronized CompletableFuture syncBackwardsUntil(final Block newPivot) { Optional> 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 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 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 stop() { - return currentBackwardSyncFuture.get(); - } - public void subscribeBadChainListener(final BadChainListener badChainListener) { badChainListeners.subscribe(badChainListener); } @@ -365,6 +361,10 @@ public Optional findMaybeFinalized() { .findFirst(); } + public Status getStatus() { + return currentBackwardSyncStatus.get(); + } + private void emitBadChainEvent(final Block badBlock) { final List badBlockDescendants = new ArrayList<>(); final List 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 currentFuture; + private long targetChainHeight; + private long initialChainHeight; + + public Status(final CompletableFuture 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; + } + } } diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java index acdfc823c6d..e22e4bbd698 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java +++ b/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> 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 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())); + } + } } diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardsSyncAlgorithm.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardsSyncAlgorithm.java index 8ff1402f282..35c3f90ec21 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardsSyncAlgorithm.java +++ b/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 pickNextStep() { final Optional 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 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 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 executeProcessKnownAncestors() { } @VisibleForTesting - public CompletableFuture executeSyncStep(final Hash hash) { + public CompletableFuture executeSyncStep(final Hash hash) { return new SyncStepStep(context, context.getBackwardChain()).executeAsync(hash); } diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java index 71c0aa26cd8..00748dd5234 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.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.ethereum.core.Block; import org.hyperledger.besu.ethereum.core.BlockHeader; @@ -34,6 +33,8 @@ public class ForwardSyncStep { private static final Logger LOG = LoggerFactory.getLogger(ForwardSyncStep.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; @@ -78,6 +79,7 @@ protected CompletableFuture> requestBodies(final List b return run.thenApply(AbstractPeerTask.PeerTaskResult::getResult) .thenApply( blocks -> { + LOG.debug("Got {} blocks from peers", blocks.size()); blocks.sort(Comparator.comparing(block -> block.getHeader().getNumber())); return blocks; }); @@ -86,8 +88,8 @@ protected CompletableFuture> requestBodies(final List b @VisibleForTesting protected Void saveBlocks(final List blocks) { if (blocks.isEmpty()) { - LOG.info("No blocks to save..."); context.halveBatchSize(); + LOG.debug("No blocks to save, reducing batch size to {}", context.getBatchSize()); return null; } @@ -97,21 +99,53 @@ protected Void saveBlocks(final List blocks) { .getProtocolContext() .getBlockchain() .getBlockByHash(block.getHeader().getParentHash()); + if (parent.isEmpty()) { context.halveBatchSize(); + debugLambda( + LOG, + "Parent block {} not found, while saving block {}, reducing batch size to {}", + block.getHeader().getParentHash()::toString, + block::toLogString, + context::getBatchSize); + logProgress(blocks.get(blocks.size() - 1).getHeader().getNumber()); return null; } else { context.saveBlock(block); } } - infoLambda( - LOG, - "Saved blocks {} -> {} (target: {})", - () -> blocks.get(0).getHeader().getNumber(), - () -> blocks.get(blocks.size() - 1).getHeader().getNumber(), - () -> - backwardChain.getPivot().orElse(blocks.get(blocks.size() - 1)).getHeader().getNumber()); + + logProgress(blocks.get(blocks.size() - 1).getHeader().getNumber()); + context.resetBatchSize(); return null; } + + private void logProgress(final long currImportedHeight) { + final long targetHeight = context.getStatus().getTargetChainHeight(); + final long initialHeight = context.getStatus().getInitialChainHeight(); + final long estimatedTotal = targetHeight - initialHeight; + final long imported = currImportedHeight - initialHeight; + + final float completedPercentage = 100.0f * imported / estimatedTotal; + + if (currImportedHeight < targetHeight) { + final long now = System.currentTimeMillis(); + if (now - lastLogAt > MILLIS_DELAY_BETWEEN_PROGRESS_LOG) { + LOG.info( + String.format( + "Backward sync phase 2 of 2, %.2f%% completed, imported %d blocks of at least %d. Peers: %d", + completedPercentage, + imported, + estimatedTotal, + context.getEthContext().getEthPeers().peerCount())); + lastLogAt = now; + } + } else { + LOG.info( + String.format( + "Backward sync phase 2 of 2 completed, imported a total of %d blocks. Peers: %d", + imported, context.getEthContext().getEthPeers().peerCount())); + } + } } diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/SyncStepStep.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/SyncStepStep.java index 88ddc18b2c6..f15a4d2b6d8 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/SyncStepStep.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/SyncStepStep.java @@ -17,6 +17,7 @@ package org.hyperledger.besu.ethereum.eth.sync.backwardsync; +import static org.hyperledger.besu.util.Slf4jLambdaHelper.debugLambda; import static org.slf4j.LoggerFactory.getLogger; import org.hyperledger.besu.datatypes.Hash; @@ -41,13 +42,14 @@ public SyncStepStep(final BackwardSyncContext context, final BackwardChain backw this.backwardChain = backwardChain; } - public CompletableFuture executeAsync(final Hash hash) { + public CompletableFuture executeAsync(final Hash hash) { return CompletableFuture.supplyAsync(() -> hash) .thenCompose(this::requestBlock) .thenApply(this::saveBlock); } private CompletableFuture requestBlock(final Hash targetHash) { + debugLambda(LOG, "Fetching block by hash {} from peers", targetHash::toString); final RetryingGetBlockFromPeersTask getBlockTask = RetryingGetBlockFromPeersTask.create( context.getProtocolSchedule(), @@ -63,10 +65,9 @@ private CompletableFuture requestBlock(final Hash targetHash) { .thenApply(AbstractPeerTask.PeerTaskResult::getResult); } - private Void saveBlock(final Block block) { - LOG.debug( - "Appending block {}({})", block.getHeader().getNumber(), block.getHash().toHexString()); + private Block saveBlock(final Block block) { + debugLambda(LOG, "Appending fetched block {}", block::toLogString); backwardChain.appendTrustedBlock(block); - return null; + return block; } } From 65af5ef215c2995aedc3797f4b489a38c0161d7a Mon Sep 17 00:00:00 2001 From: Fabio Di Fabio Date: Fri, 11 Nov 2022 12:59:50 +0100 Subject: [PATCH 2/8] Add CHANGELOG entry Signed-off-by: Fabio Di Fabio --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index c6cf27dc902..b6e5aeeb9d7 100644 --- a/CHANGELOG.md +++ b/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 From 5003ad75c1c46b646038720960d2114b14dd4047 Mon Sep 17 00:00:00 2001 From: Fabio Di Fabio Date: Fri, 11 Nov 2022 16:25:52 +0100 Subject: [PATCH 3/8] Fix log in case of sync failures Signed-off-by: Fabio Di Fabio --- .../merge/blockcreation/MergeCoordinator.java | 6 +++++- .../internal/methods/engine/EngineNewPayload.java | 7 +++++-- .../eth/sync/backwardsync/BackwardSyncContext.java | 11 +++++++---- .../eth/sync/backwardsync/BackwardSyncStep.java | 2 +- .../eth/sync/backwardsync/ForwardSyncStep.java | 10 +++++++--- 5 files changed, 25 insertions(+), 11 deletions(-) diff --git a/consensus/merge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java b/consensus/merge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java index 438d294602c..d907ccdc7b4 100644 --- a/consensus/merge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java +++ b/consensus/merge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java @@ -390,7 +390,11 @@ public Optional 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/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineNewPayload.java b/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineNewPayload.java index 7390b9d80f0..f0636c02d1b 100644 --- a/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineNewPayload.java +++ b/ethereum/api/src/main/java/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/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java index fb941722733..f34cf5561bb 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java @@ -131,6 +131,7 @@ public synchronized CompletableFuture 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 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 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/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java index e22e4bbd698..2b15940eacd 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java +++ b/ethereum/eth/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/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java index 00748dd5234..18a83ecebe2 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java @@ -93,6 +93,9 @@ protected Void saveBlocks(final List blocks) { return null; } + long lastImportedHeight = + context.getProtocolContext().getBlockchain().getChainHeadBlockNumber(); + for (Block block : blocks) { final Optional parent = context @@ -108,14 +111,15 @@ protected Void saveBlocks(final List 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( From ca71f6e0caaaf9e9e6960598cfa2fe7bc0e4ddb3 Mon Sep 17 00:00:00 2001 From: Fabio Di Fabio Date: Fri, 11 Nov 2022 12:58:23 +0100 Subject: [PATCH 4/8] Backward sync log UX improvements Signed-off-by: Fabio Di Fabio --- .../merge/blockcreation/MergeCoordinator.java | 2 +- .../task/RetryingGetBlockFromPeersTask.java | 7 +- .../backwardsync/BackwardSyncContext.java | 71 +++++++++++++------ .../sync/backwardsync/BackwardSyncStep.java | 42 ++++++++--- .../backwardsync/BackwardsSyncAlgorithm.java | 26 ++++--- .../sync/backwardsync/ForwardSyncStep.java | 52 +++++++++++--- .../eth/sync/backwardsync/SyncStepStep.java | 11 +-- 7 files changed, 155 insertions(+), 56 deletions(-) diff --git a/consensus/merge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java b/consensus/merge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java index 4ca248546fa..438d294602c 100644 --- a/consensus/merge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java +++ b/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); } diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/RetryingGetBlockFromPeersTask.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/RetryingGetBlockFromPeersTask.java index c1894189065..7d5062ec74d 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/RetryingGetBlockFromPeersTask.java +++ b/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); } diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java index deb94063441..fb941722733 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java +++ b/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> currentBackwardSyncFuture = - new AtomicReference<>(); + private final AtomicReference currentBackwardSyncStatus = new AtomicReference<>(); private final BackwardChain backwardChain; private int batchSize = BATCH_SIZE; private Optional 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 syncBackwardsUntil(final Hash newBlockHash) { Optional> 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 future = prepareBackwardSyncFutureWithRetry(); - this.currentBackwardSyncFuture.set(future); - return future; + Status status = new Status(prepareBackwardSyncFutureWithRetry()); + this.currentBackwardSyncStatus.set(status); + return status.currentFuture; }); } public synchronized CompletableFuture syncBackwardsUntil(final Block newPivot) { Optional> 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 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 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 stop() { - return currentBackwardSyncFuture.get(); - } - public void subscribeBadChainListener(final BadChainListener badChainListener) { badChainListeners.subscribe(badChainListener); } @@ -365,6 +361,10 @@ public Optional findMaybeFinalized() { .findFirst(); } + public Status getStatus() { + return currentBackwardSyncStatus.get(); + } + private void emitBadChainEvent(final Block badBlock) { final List badBlockDescendants = new ArrayList<>(); final List 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 currentFuture; + private long targetChainHeight; + private long initialChainHeight; + + public Status(final CompletableFuture 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; + } + } } diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java index acdfc823c6d..e22e4bbd698 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java +++ b/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> 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 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())); + } + } } diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardsSyncAlgorithm.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardsSyncAlgorithm.java index 8ff1402f282..35c3f90ec21 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardsSyncAlgorithm.java +++ b/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 pickNextStep() { final Optional 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 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 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 executeProcessKnownAncestors() { } @VisibleForTesting - public CompletableFuture executeSyncStep(final Hash hash) { + public CompletableFuture executeSyncStep(final Hash hash) { return new SyncStepStep(context, context.getBackwardChain()).executeAsync(hash); } diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java index 71c0aa26cd8..00748dd5234 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.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.ethereum.core.Block; import org.hyperledger.besu.ethereum.core.BlockHeader; @@ -34,6 +33,8 @@ public class ForwardSyncStep { private static final Logger LOG = LoggerFactory.getLogger(ForwardSyncStep.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; @@ -78,6 +79,7 @@ protected CompletableFuture> requestBodies(final List b return run.thenApply(AbstractPeerTask.PeerTaskResult::getResult) .thenApply( blocks -> { + LOG.debug("Got {} blocks from peers", blocks.size()); blocks.sort(Comparator.comparing(block -> block.getHeader().getNumber())); return blocks; }); @@ -86,8 +88,8 @@ protected CompletableFuture> requestBodies(final List b @VisibleForTesting protected Void saveBlocks(final List blocks) { if (blocks.isEmpty()) { - LOG.info("No blocks to save..."); context.halveBatchSize(); + LOG.debug("No blocks to save, reducing batch size to {}", context.getBatchSize()); return null; } @@ -97,21 +99,53 @@ protected Void saveBlocks(final List blocks) { .getProtocolContext() .getBlockchain() .getBlockByHash(block.getHeader().getParentHash()); + if (parent.isEmpty()) { context.halveBatchSize(); + debugLambda( + LOG, + "Parent block {} not found, while saving block {}, reducing batch size to {}", + block.getHeader().getParentHash()::toString, + block::toLogString, + context::getBatchSize); + logProgress(blocks.get(blocks.size() - 1).getHeader().getNumber()); return null; } else { context.saveBlock(block); } } - infoLambda( - LOG, - "Saved blocks {} -> {} (target: {})", - () -> blocks.get(0).getHeader().getNumber(), - () -> blocks.get(blocks.size() - 1).getHeader().getNumber(), - () -> - backwardChain.getPivot().orElse(blocks.get(blocks.size() - 1)).getHeader().getNumber()); + + logProgress(blocks.get(blocks.size() - 1).getHeader().getNumber()); + context.resetBatchSize(); return null; } + + private void logProgress(final long currImportedHeight) { + final long targetHeight = context.getStatus().getTargetChainHeight(); + final long initialHeight = context.getStatus().getInitialChainHeight(); + final long estimatedTotal = targetHeight - initialHeight; + final long imported = currImportedHeight - initialHeight; + + final float completedPercentage = 100.0f * imported / estimatedTotal; + + if (currImportedHeight < targetHeight) { + final long now = System.currentTimeMillis(); + if (now - lastLogAt > MILLIS_DELAY_BETWEEN_PROGRESS_LOG) { + LOG.info( + String.format( + "Backward sync phase 2 of 2, %.2f%% completed, imported %d blocks of at least %d. Peers: %d", + completedPercentage, + imported, + estimatedTotal, + context.getEthContext().getEthPeers().peerCount())); + lastLogAt = now; + } + } else { + LOG.info( + String.format( + "Backward sync phase 2 of 2 completed, imported a total of %d blocks. Peers: %d", + imported, context.getEthContext().getEthPeers().peerCount())); + } + } } diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/SyncStepStep.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/SyncStepStep.java index 88ddc18b2c6..f15a4d2b6d8 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/SyncStepStep.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/SyncStepStep.java @@ -17,6 +17,7 @@ package org.hyperledger.besu.ethereum.eth.sync.backwardsync; +import static org.hyperledger.besu.util.Slf4jLambdaHelper.debugLambda; import static org.slf4j.LoggerFactory.getLogger; import org.hyperledger.besu.datatypes.Hash; @@ -41,13 +42,14 @@ public SyncStepStep(final BackwardSyncContext context, final BackwardChain backw this.backwardChain = backwardChain; } - public CompletableFuture executeAsync(final Hash hash) { + public CompletableFuture executeAsync(final Hash hash) { return CompletableFuture.supplyAsync(() -> hash) .thenCompose(this::requestBlock) .thenApply(this::saveBlock); } private CompletableFuture requestBlock(final Hash targetHash) { + debugLambda(LOG, "Fetching block by hash {} from peers", targetHash::toString); final RetryingGetBlockFromPeersTask getBlockTask = RetryingGetBlockFromPeersTask.create( context.getProtocolSchedule(), @@ -63,10 +65,9 @@ private CompletableFuture requestBlock(final Hash targetHash) { .thenApply(AbstractPeerTask.PeerTaskResult::getResult); } - private Void saveBlock(final Block block) { - LOG.debug( - "Appending block {}({})", block.getHeader().getNumber(), block.getHash().toHexString()); + private Block saveBlock(final Block block) { + debugLambda(LOG, "Appending fetched block {}", block::toLogString); backwardChain.appendTrustedBlock(block); - return null; + return block; } } From 00a54686fbcc6a98ebc7598ec472cf7aaa5acb5d Mon Sep 17 00:00:00 2001 From: Fabio Di Fabio Date: Fri, 11 Nov 2022 12:59:50 +0100 Subject: [PATCH 5/8] Add CHANGELOG entry Signed-off-by: Fabio Di Fabio --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index c0e56539154..815136aa0b3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,7 @@ - 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) - Upgrade RocksDB version from 7.6.0 to 7.7.3 +- Backward sync log UX improvements [#4655](https://github.com/hyperledger/besu/pull/4655) ### Bug Fixes From 0ad7d31bd6438db98092d32e3b70ca3f3c759bf3 Mon Sep 17 00:00:00 2001 From: Fabio Di Fabio Date: Fri, 11 Nov 2022 16:25:52 +0100 Subject: [PATCH 6/8] Fix log in case of sync failures Signed-off-by: Fabio Di Fabio --- .../merge/blockcreation/MergeCoordinator.java | 6 +++++- .../internal/methods/engine/EngineNewPayload.java | 7 +++++-- .../eth/sync/backwardsync/BackwardSyncContext.java | 11 +++++++---- .../eth/sync/backwardsync/BackwardSyncStep.java | 2 +- .../eth/sync/backwardsync/ForwardSyncStep.java | 10 +++++++--- 5 files changed, 25 insertions(+), 11 deletions(-) diff --git a/consensus/merge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java b/consensus/merge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java index 438d294602c..d907ccdc7b4 100644 --- a/consensus/merge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java +++ b/consensus/merge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java @@ -390,7 +390,11 @@ public Optional 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/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineNewPayload.java b/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineNewPayload.java index 7390b9d80f0..f0636c02d1b 100644 --- a/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineNewPayload.java +++ b/ethereum/api/src/main/java/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/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java index fb941722733..f34cf5561bb 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java @@ -131,6 +131,7 @@ public synchronized CompletableFuture 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 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 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/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java index e22e4bbd698..2b15940eacd 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java +++ b/ethereum/eth/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/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java index 00748dd5234..18a83ecebe2 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java @@ -93,6 +93,9 @@ protected Void saveBlocks(final List blocks) { return null; } + long lastImportedHeight = + context.getProtocolContext().getBlockchain().getChainHeadBlockNumber(); + for (Block block : blocks) { final Optional parent = context @@ -108,14 +111,15 @@ protected Void saveBlocks(final List 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( From 6c0c302fc79ebbf9c8d317c19d351e3522a3b315 Mon Sep 17 00:00:00 2001 From: Fabio Di Fabio Date: Mon, 14 Nov 2022 14:41:38 +0100 Subject: [PATCH 7/8] Rework log of imported block to support also ProcessKnownAncestorsStep Signed-off-by: Fabio Di Fabio --- .../backwardsync/BackwardSyncContext.java | 113 +++++++++++++----- .../sync/backwardsync/BackwardSyncStep.java | 6 +- .../sync/backwardsync/ForwardSyncStep.java | 37 ------ 3 files changed, 87 insertions(+), 69 deletions(-) diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java index f34cf5561bb..f52ac4cdc28 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java @@ -47,7 +47,7 @@ public class BackwardSyncContext { private static final Logger LOG = LoggerFactory.getLogger(BackwardSyncContext.class); public static final int BATCH_SIZE = 200; private static final int DEFAULT_MAX_RETRIES = 20; - + private static final long MILLIS_DELAY_BETWEEN_PROGRESS_LOG = 10_000L; private static final long DEFAULT_MILLIS_BETWEEN_RETRIES = 5000; protected final ProtocolContext protocolContext; @@ -122,41 +122,51 @@ public synchronized void updateHeads(final Hash head, final Hash finalizedBlockH } public synchronized CompletableFuture syncBackwardsUntil(final Hash newBlockHash) { - Optional> maybeFuture = - Optional.ofNullable(this.currentBackwardSyncStatus.get()) - .map(status -> status.currentFuture); + Optional maybeCurrentStatus = Optional.ofNullable(this.currentBackwardSyncStatus.get()); if (isTrusted(newBlockHash)) { - return maybeFuture.orElseGet(() -> CompletableFuture.completedFuture(null)); + return maybeCurrentStatus + .map( + status -> { + backwardChain + .getBlock(newBlockHash) + .ifPresent(block -> status.updateTargetHeight(block.getHeader().getNumber())); + return status.currentFuture; + }) + .orElseGet(() -> CompletableFuture.completedFuture(null)); } 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; - }); + return maybeCurrentStatus + .map(Status::getCurrentFuture) + .orElseGet( + () -> { + LOG.info("Starting a new backward sync session"); + Status status = new Status(prepareBackwardSyncFutureWithRetry()); + this.currentBackwardSyncStatus.set(status); + return status.currentFuture; + }); } public synchronized CompletableFuture syncBackwardsUntil(final Block newPivot) { - Optional> maybeFuture = - Optional.ofNullable(this.currentBackwardSyncStatus.get()) - .map(status -> status.currentFuture); + Optional maybeCurrentStatus = Optional.ofNullable(this.currentBackwardSyncStatus.get()); if (isTrusted(newPivot.getHash())) { - return maybeFuture.orElseGet(() -> CompletableFuture.completedFuture(null)); + return maybeCurrentStatus + .map(Status::getCurrentFuture) + .orElseGet(() -> CompletableFuture.completedFuture(null)); } 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; - }); + return maybeCurrentStatus + .map(Status::getCurrentFuture) + .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( + getProtocolContext().getBlockchain().getChainHeadBlockNumber(), + newPivot.getHeader().getNumber()); + this.currentBackwardSyncStatus.set(status); + return status.currentFuture; + }); } private boolean isTrusted(final Hash hash) { @@ -319,6 +329,7 @@ protected Void saveBlock(final Block block) { .getBlockchain() .appendBlock(block, optResult.getYield().get().getReceipts()); possiblyMoveHead(block); + logBlockImportProgress(block.getHeader().getNumber()); } else { emitBadChainEvent(block); throw new BackwardSyncException( @@ -393,11 +404,42 @@ private void emitBadChainEvent(final Block badBlock) { listener -> listener.onBadChain(badBlock, badBlockDescendants, badBlockHeaderDescendants)); } + private void logBlockImportProgress(final long currImportedHeight) { + final Status currentStatus = getStatus(); + final long targetHeight = currentStatus.getTargetChainHeight(); + final long initialHeight = currentStatus.getInitialChainHeight(); + final long estimatedTotal = targetHeight - initialHeight; + final long imported = currImportedHeight - initialHeight; + + final float completedPercentage = 100.0f * imported / estimatedTotal; + + if (completedPercentage < 100.0f) { + if (currentStatus.couldLogProgress()) { + LOG.info( + String.format( + "Backward sync phase 2 of 2, %.2f%% completed, imported %d blocks of at least %d (current head %d, target head %d). Peers: %d", + completedPercentage, + imported, + estimatedTotal, + currImportedHeight, + currentStatus.getTargetChainHeight(), + getEthContext().getEthPeers().peerCount())); + } + } else { + LOG.info( + String.format( + "Backward sync phase 2 of 2 completed, imported a total of %d blocks. Peers: %d", + imported, getEthContext().getEthPeers().peerCount())); + } + } + static class Status { private final CompletableFuture currentFuture; private long targetChainHeight; private long initialChainHeight; + private static long lastLogAt = 0; + public Status(final CompletableFuture currentFuture) { this.currentFuture = currentFuture; } @@ -407,6 +449,23 @@ public void setSyncRange(final long initialHeight, final long targetHeight) { targetChainHeight = targetHeight; } + public void updateTargetHeight(final long newTargetHeight) { + targetChainHeight = newTargetHeight; + } + + public boolean couldLogProgress() { + final long now = System.currentTimeMillis(); + if (now - lastLogAt > MILLIS_DELAY_BETWEEN_PROGRESS_LOG) { + lastLogAt = now; + return true; + } + return false; + } + + public CompletableFuture getCurrentFuture() { + return currentFuture; + } + public long getTargetChainHeight() { return targetChainHeight; } diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java index 2b15940eacd..c13276d013f 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java @@ -30,8 +30,6 @@ 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; @@ -117,8 +115,7 @@ private void logProgress(final long currLowestDownloadedHeight) { final float completedPercentage = 100.0f * downloaded / estimatedTotal; if (completedPercentage < 100.0f) { - final long now = System.currentTimeMillis(); - if (now - lastLogAt > MILLIS_DELAY_BETWEEN_PROGRESS_LOG) { + if (context.getStatus().couldLogProgress()) { LOG.info( String.format( "Backward sync phase 1 of 2, %.2f%% completed, downloaded %d headers of at least %d. Peers: %d", @@ -126,7 +123,6 @@ private void logProgress(final long currLowestDownloadedHeight) { downloaded, estimatedTotal, context.getEthContext().getEthPeers().peerCount())); - lastLogAt = now; } } else { LOG.info( diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java index 18a83ecebe2..37035d5ed4f 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/ForwardSyncStep.java @@ -33,8 +33,6 @@ public class ForwardSyncStep { private static final Logger LOG = LoggerFactory.getLogger(ForwardSyncStep.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; @@ -93,9 +91,6 @@ protected Void saveBlocks(final List blocks) { return null; } - long lastImportedHeight = - context.getProtocolContext().getBlockchain().getChainHeadBlockNumber(); - for (Block block : blocks) { final Optional parent = context @@ -111,45 +106,13 @@ protected Void saveBlocks(final List blocks) { block.getHeader().getParentHash()::toString, block::toLogString, context::getBatchSize); - logProgress(lastImportedHeight); return null; } else { context.saveBlock(block); - lastImportedHeight = block.getHeader().getNumber(); } } - logProgress(lastImportedHeight); - context.resetBatchSize(); return null; } - - private void logProgress(final long currImportedHeight) { - final long targetHeight = context.getStatus().getTargetChainHeight(); - final long initialHeight = context.getStatus().getInitialChainHeight(); - final long estimatedTotal = targetHeight - initialHeight; - final long imported = currImportedHeight - initialHeight; - - final float completedPercentage = 100.0f * imported / estimatedTotal; - - if (completedPercentage < 100.0f) { - final long now = System.currentTimeMillis(); - if (now - lastLogAt > MILLIS_DELAY_BETWEEN_PROGRESS_LOG) { - LOG.info( - String.format( - "Backward sync phase 2 of 2, %.2f%% completed, imported %d blocks of at least %d. Peers: %d", - completedPercentage, - imported, - estimatedTotal, - context.getEthContext().getEthPeers().peerCount())); - lastLogAt = now; - } - } else { - LOG.info( - String.format( - "Backward sync phase 2 of 2 completed, imported a total of %d blocks. Peers: %d", - imported, context.getEthContext().getEthPeers().peerCount())); - } - } } From d7f55d403b448f9cb723ac3555b17a44df2b07e5 Mon Sep 17 00:00:00 2001 From: Fabio Di Fabio Date: Tue, 15 Nov 2022 11:09:44 +0100 Subject: [PATCH 8/8] Improve method naming Signed-off-by: Fabio Di Fabio --- .../ethereum/eth/sync/backwardsync/BackwardSyncContext.java | 4 ++-- .../besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java index f52ac4cdc28..c0f3ef9dbed 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java @@ -414,7 +414,7 @@ private void logBlockImportProgress(final long currImportedHeight) { final float completedPercentage = 100.0f * imported / estimatedTotal; if (completedPercentage < 100.0f) { - if (currentStatus.couldLogProgress()) { + if (currentStatus.progressLogDue()) { LOG.info( String.format( "Backward sync phase 2 of 2, %.2f%% completed, imported %d blocks of at least %d (current head %d, target head %d). Peers: %d", @@ -453,7 +453,7 @@ public void updateTargetHeight(final long newTargetHeight) { targetChainHeight = newTargetHeight; } - public boolean couldLogProgress() { + public boolean progressLogDue() { final long now = System.currentTimeMillis(); if (now - lastLogAt > MILLIS_DELAY_BETWEEN_PROGRESS_LOG) { lastLogAt = now; diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java index c13276d013f..344df922162 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java @@ -115,7 +115,7 @@ private void logProgress(final long currLowestDownloadedHeight) { final float completedPercentage = 100.0f * downloaded / estimatedTotal; if (completedPercentage < 100.0f) { - if (context.getStatus().couldLogProgress()) { + if (context.getStatus().progressLogDue()) { LOG.info( String.format( "Backward sync phase 1 of 2, %.2f%% completed, downloaded %d headers of at least %d. Peers: %d",