Remove maybeHead from BackwardSyncContext (hyperledger#5497)

Its usage is not clear and it's causing besu to rewind the head to it (a large reorg) when combined with nimbus backwards sync. Add more backwards sync logging. Signed-off-by: Simon Dudley <simon.dudley@consensys.net> Co-authored-by: Fabio Di Fabio <fabio.difabio@consensys.net> Co-authored-by: Sally MacFarlane <macfarla.github@gmail.com>
liquichain · Jun 28, 2023 · d244936 · d244936
1 parent 626612d
commit d244936
Show file tree

Hide file tree

Showing 7 changed files with 68 additions and 30 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -18,6 +18,7 @@ and in case a rollback is needed, before installing a previous version, the migr
 - Add healing flat db mechanism with experimental CLI options `--Xsnapsync-synchronizer-flat-db-healing-enabled=true` [#5319](https://github.com/hyperledger/besu/pull/5319)
 
 ### Bug Fixes
+- Fix backwards sync bug where chain is rolled back too far, especially when restarting Nimbus [#5497](https://github.com/hyperledger/besu/pull/5497)
 - Check to ensure storage and transactions are not closed prior to reading/writing [#5527](https://github.com/hyperledger/besu/pull/5527) 
 - Fix the unavailability of account code and storage on GraphQl/Bonsai [#5548](https://github.com/hyperledger/besu/pull/5548)
 

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
@@ -467,7 +467,7 @@ public Optional<BlockHeader> getOrSyncHeadByHash(final Hash headHash, final Hash
           .setMessage("Appending new head block hash {} to backward sync")
           .addArgument(headHash::toHexString)
           .log();
-      backwardSyncContext.updateHead(headHash);
+      backwardSyncContext.maybeUpdateTargetHeight(headHash);
       backwardSyncContext
           .syncBackwardsUntil(headHash)
           .thenRun(() -> updateFinalized(finalizedHash));

diff --git a/.../src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/EthGetLogs.java b/.../src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/EthGetLogs.java
@@ -53,6 +53,7 @@ public String getName() {
   @Override
   public JsonRpcResponse response(final JsonRpcRequestContext requestContext) {
     final FilterParameter filter = requestContext.getRequiredParameter(0, FilterParameter.class);
+    LOG.atTrace().setMessage("eth_getLogs FilterParameter: {}").addArgument(filter).log();
 
     if (!filter.isValid()) {
       return new JsonRpcErrorResponse(

diff --git a/...h/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetBodiesFromPeerTask.java b/...h/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetBodiesFromPeerTask.java
@@ -84,6 +84,11 @@ public static GetBodiesFromPeerTask forHeaders(
   protected PendingPeerRequest sendRequest() {
     final List<Hash> blockHashes =
         headers.stream().map(BlockHeader::getHash).collect(Collectors.toList());
+    LOG.atTrace()
+        .setMessage("Requesting {} bodies with hashes {}.")
+        .addArgument(blockHashes.size())
+        .addArgument(blockHashes)
+        .log();
     final long minimumRequiredBlockNumber = headers.get(headers.size() - 1).getNumber();
 
     return sendRequestToPeer(
@@ -128,6 +133,13 @@ protected Optional<List<Block>> processResponse(
       // Clear processed headers
       headers.clear();
     }
+    LOG.atTrace()
+        .setMessage("Associated {} bodies with {} headers to get {} blocks with these hashes: {}")
+        .addArgument(bodies.size())
+        .addArgument(headers.size())
+        .addArgument(blocks.size())
+        .addArgument(() -> blocks.stream().map(Block::toLogString).toList())
+        .log();
     return Optional.of(blocks);
   }
 

diff --git a/...erledger/besu/ethereum/eth/manager/task/RetryingGetHeadersEndingAtFromPeerByHashTask.java b/...erledger/besu/ethereum/eth/manager/task/RetryingGetHeadersEndingAtFromPeerByHashTask.java
@@ -92,8 +92,8 @@ protected CompletableFuture<List<BlockHeader>> executeTaskOnCurrentPeer(
     return executeSubTask(task::run)
         .thenApply(
             peerResult -> {
-              LOG.debug(
-                  "Get {} block headers by hash {} from peer {} has result {}",
+              LOG.trace(
+                  "Got {} block headers by hash {} from peer {} has result {}",
                   count,
                   referenceHash,
                   currentPeer,

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
@@ -55,7 +55,6 @@ public class BackwardSyncContext {
   private final AtomicReference<Status> currentBackwardSyncStatus = new AtomicReference<>();
   private final BackwardChain backwardChain;
   private int batchSize = BATCH_SIZE;
-  private Optional<Hash> maybeHead = Optional.empty();
   private final int maxRetries;
   private final long millisBetweenRetries = DEFAULT_MILLIS_BETWEEN_RETRIES;
   private final Subscribers<BadChainListener> badChainListeners = Subscribers.create();
@@ -101,17 +100,21 @@ public synchronized boolean isSyncing() {
         .orElse(Boolean.FALSE);
   }
 
-  public synchronized void updateHead(final Hash headHash) {
-    if (Hash.ZERO.equals(headHash)) {
-      maybeHead = Optional.empty();
-    } else {
-      maybeHead = Optional.of(headHash);
+  public synchronized void maybeUpdateTargetHeight(final Hash headHash) {
+    if (!Hash.ZERO.equals(headHash)) {
       Optional<Status> maybeCurrentStatus = Optional.ofNullable(currentBackwardSyncStatus.get());
       maybeCurrentStatus.ifPresent(
           status ->
               backwardChain
                   .getBlock(headHash)
-                  .ifPresent(block -> status.updateTargetHeight(block.getHeader().getNumber())));
+                  .ifPresent(
+                      block -> {
+                        LOG.atTrace()
+                            .setMessage("updateTargetHeight to {}")
+                            .addArgument(block::toLogString)
+                            .log();
+                        status.updateTargetHeight(block.getHeader().getNumber());
+                      }));
     }
   }
 
@@ -331,20 +334,12 @@ protected Void saveBlock(final Block block) {
   @VisibleForTesting
   protected void possiblyMoveHead(final Block lastSavedBlock) {
     final MutableBlockchain blockchain = getProtocolContext().getBlockchain();
-    if (maybeHead.isEmpty()) {
-      LOG.debug("Nothing to do with the head");
-      return;
-    }
-
-    final Hash head = maybeHead.get();
-    if (blockchain.getChainHead().getHash().equals(head)) {
-      LOG.debug("Head is already properly set");
-      return;
-    }
 
-    if (blockchain.contains(head)) {
-      LOG.debug("Changing head to {}", head);
-      blockchain.rewindToBlock(head);
+    if (blockchain.getChainHead().getHash().equals(lastSavedBlock.getHash())) {
+      LOG.atDebug()
+          .setMessage("Head is already properly set to {}")
+          .addArgument(lastSavedBlock::toLogString)
+          .log();
       return;
     }
 
@@ -442,10 +437,6 @@ public boolean progressLogDue() {
       return false;
     }
 
-    public CompletableFuture<Void> getCurrentFuture() {
-      return currentFuture;
-    }
-
     public long getTargetChainHeight() {
       return targetChainHeight;
     }

diff --git a/...est/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContextTest.java b/...est/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContextTest.java
@@ -59,6 +59,7 @@
 import java.util.concurrent.ExecutionException;
 import javax.annotation.Nonnull;
 
+import org.apache.tuweni.bytes.Bytes;
 import org.junit.Before;
 import org.junit.Test;
 import org.junit.runner.RunWith;
@@ -256,13 +257,45 @@ private Block getBlockByNumber(final int number) {
   }
 
   @Test
-  public void testUpdatingHead() {
-    context.updateHead(localBlockchain.getBlockByNumber(4).orElseThrow().getHash());
-    context.possiblyMoveHead(null);
+  public void shouldMoveHead() {
+    final Block lastSavedBlock = localBlockchain.getBlockByNumber(4).orElseThrow();
+    context.possiblyMoveHead(lastSavedBlock);
 
     assertThat(localBlockchain.getChainHeadBlock().getHeader().getNumber()).isEqualTo(4);
   }
 
+  @Test
+  public void shouldNotMoveHeadWhenAlreadyHead() {
+    final Block lastSavedBlock = localBlockchain.getBlockByNumber(25).orElseThrow();
+    context.possiblyMoveHead(lastSavedBlock);
+
+    assertThat(localBlockchain.getChainHeadBlock().getHeader().getNumber()).isEqualTo(25);
+  }
+
+  @Test
+  public void shouldUpdateTargetHeightWhenStatusPresent() {
+    // Given
+    BlockHeader blockHeader = Mockito.mock(BlockHeader.class);
+    when(blockHeader.getParentHash()).thenReturn(Hash.fromHexStringLenient("0x41"));
+    when(blockHeader.getHash()).thenReturn(Hash.fromHexStringLenient("0x42"));
+    when(blockHeader.getNumber()).thenReturn(42L);
+    Block unknownBlock = Mockito.mock(Block.class);
+    when(unknownBlock.getHeader()).thenReturn(blockHeader);
+    when(unknownBlock.getHash()).thenReturn(Hash.fromHexStringLenient("0x42"));
+    when(unknownBlock.toRlp()).thenReturn(Bytes.EMPTY);
+    context.syncBackwardsUntil(unknownBlock); // set the status
+    assertThat(context.getStatus().getTargetChainHeight()).isEqualTo(42);
+    final Hash backwardChainHash =
+        remoteBlockchain.getBlockByNumber(LOCAL_HEIGHT + 4).get().getHash();
+    final Block backwardChainBlock = backwardChain.getTrustedBlock(backwardChainHash);
+
+    // When
+    context.maybeUpdateTargetHeight(backwardChainBlock.getHash());
+
+    // Then
+    assertThat(context.getStatus().getTargetChainHeight()).isEqualTo(29);
+  }
+
   @Test
   public void shouldProcessExceptionsCorrectly() {
     assertThatThrownBy(