Reorg Logging (#1349)

Signed-off-by: Ratan Rai Sur <ratan.r.sur@gmail.com>

CHANGELOG.md

@@ -5,6 +5,7 @@
 ### Additions and Improvements
 
 * Added `priv_debugGetStateRoot` JSON-RPC API to retrieve the state root of a specified privacy group. [\#1326](https://github.com/hyperledger/besu/pull/1326)
+* Added reorg logging and `--reorg-logging-threshold` to configure the same. Besu now logs any reorgs where the old or new chain head is more than the threshold away from their common ancestors. The default is 6.
 
 ### Bug Fixes
 

besu/src/main/java/org/hyperledger/besu/cli/BesuCommand.java

@@ -722,6 +722,12 @@ public class BesuCommand implements DefaultCommandValues, Runnable {
           "Force color output to be enabled/disabled (default: colorized only if printing to console")
   private static Boolean colorEnabled = null;
 
+  @Option(
+      names = {"--reorg-logging-threshold"},
+      description =
+          "How deep a chain reorganization must be in order for it to be logged (default: ${DEFAULT-VALUE})")
+  private final Long reorgLoggingThreshold = 6L;
+
   @Option(
       names = {"--miner-enabled"},
       description = "Set if node will perform mining (default: ${DEFAULT-VALUE})")
@@ -1543,7 +1549,8 @@ public class BesuCommand implements DefaultCommandValues, Runnable {
             new PrunerConfiguration(pruningBlockConfirmations, pruningBlocksRetained))
         .genesisConfigOverrides(genesisConfigOverrides)
         .targetGasLimit(targetGasLimit == null ? Optional.empty() : Optional.of(targetGasLimit))
-        .requiredBlocks(requiredBlocks);
+        .requiredBlocks(requiredBlocks)
+        .reorgLoggingThreshold(reorgLoggingThreshold);
   }
 
   private GraphQLConfiguration graphQLConfiguration() {

besu/src/main/java/org/hyperledger/besu/controller/BesuControllerBuilder.java

@@ -93,6 +93,7 @@ public abstract class BesuControllerBuilder {
   private PrunerConfiguration prunerConfiguration;
   Map<String, String> genesisConfigOverrides;
   private Map<Long, Hash> requiredBlocks = Collections.emptyMap();
+  private long reorgLoggingThreshold;
 
   public BesuControllerBuilder storageProvider(final StorageProvider storageProvider) {
     this.storageProvider = storageProvider;
@@ -188,6 +189,11 @@ public abstract class BesuControllerBuilder {
     return this;
   }
 
+  public BesuControllerBuilder reorgLoggingThreshold(final long reorgLoggingThreshold) {
+    this.reorgLoggingThreshold = reorgLoggingThreshold;
+    return this;
+  }
+
   public BesuController build() {
     checkNotNull(genesisConfig, "Missing genesis config");
     checkNotNull(syncConfig, "Missing sync config");
@@ -213,7 +219,8 @@ public abstract class BesuControllerBuilder {
             genesisState,
             protocolSchedule,
             metricsSystem,
-            this::createConsensusContext);
+            this::createConsensusContext,
+            reorgLoggingThreshold);
     validateContext(protocolContext);
 
     protocolSchedule.setPublicWorldStateArchiveForPrivacyBlockProcessor(

besu/src/test/java/org/hyperledger/besu/cli/CommandTestAbstract.java

@@ -18,6 +18,7 @@ import static org.mockito.ArgumentMatchers.any;
 import static org.mockito.ArgumentMatchers.anyBoolean;
 import static org.mockito.ArgumentMatchers.anyFloat;
 import static org.mockito.ArgumentMatchers.anyInt;
+import static org.mockito.ArgumentMatchers.anyLong;
 import static org.mockito.ArgumentMatchers.anyString;
 import static org.mockito.ArgumentMatchers.eq;
 import static org.mockito.Mockito.doReturn;
@@ -185,6 +186,7 @@ public abstract class CommandTestAbstract {
     when(mockControllerBuilder.genesisConfigOverrides(any())).thenReturn(mockControllerBuilder);
     when(mockControllerBuilder.targetGasLimit(any())).thenReturn(mockControllerBuilder);
     when(mockControllerBuilder.requiredBlocks(any())).thenReturn(mockControllerBuilder);
+    when(mockControllerBuilder.reorgLoggingThreshold(anyLong())).thenReturn(mockControllerBuilder);
 
     // doReturn used because of generic BesuController
     doReturn(mockController).when(mockControllerBuilder).build();

besu/src/test/java/org/hyperledger/besu/services/BesuEventsImplTest.java

@@ -105,7 +105,8 @@ public class BesuEventsImplTest {
             gen.genesisBlock(),
             new KeyValueStoragePrefixedKeyBlockchainStorage(
                 new InMemoryKeyValueStorage(), new MainnetBlockHeaderFunctions()),
-            new NoOpMetricsSystem());
+            new NoOpMetricsSystem(),
+            0);
 
     when(mockEthContext.getEthMessages()).thenReturn(mockEthMessages);
     when(mockEthContext.getEthPeers()).thenReturn(mockEthPeers);

besu/src/test/resources/everything_config.toml

@@ -14,6 +14,7 @@ logging="INFO"
 color-enabled=false
 node-private-key-file="./path/to/privateKey"
 pid-path="~/.pid"
+reorg-logging-threshold=0
 
 # Security Module plugin to use
 security-module="localfile"

ethereum/api/src/test/java/org/hyperledger/besu/ethereum/api/jsonrpc/websocket/subscription/blockheaders/NewBlockHeadersSubscriptionServiceTest.java

@@ -63,7 +63,7 @@ public class NewBlockHeadersSubscriptionServiceTest {
           new InMemoryKeyValueStorage(), new MainnetBlockHeaderFunctions());
   private final Block genesisBlock = gen.genesisBlock();
   private final MutableBlockchain blockchain =
-      DefaultBlockchain.createMutable(genesisBlock, blockchainStorage, new NoOpMetricsSystem());
+      DefaultBlockchain.createMutable(genesisBlock, blockchainStorage, new NoOpMetricsSystem(), 0);
 
   @Spy
   private final SubscriptionManager subscriptionManagerSpy =

ethereum/core/src/main/java/org/hyperledger/besu/ethereum/ProtocolContext.java

@@ -52,7 +52,8 @@ public class ProtocolContext {
       final GenesisState genesisState,
       final ProtocolSchedule protocolSchedule,
       final MetricsSystem metricsSystem,
-      final BiFunction<Blockchain, WorldStateArchive, Object> consensusContextFactory) {
+      final BiFunction<Blockchain, WorldStateArchive, Object> consensusContextFactory,
+      final long reorgLoggingThreshold) {
     final BlockchainStorage blockchainStorage =
         storageProvider.createBlockchainStorage(protocolSchedule);
     final WorldStateStorage worldStateStorage = storageProvider.createWorldStateStorage();
@@ -60,7 +61,8 @@ public class ProtocolContext {
         storageProvider.createWorldStatePreimageStorage();
 
     final MutableBlockchain blockchain =
-        DefaultBlockchain.createMutable(genesisState.getBlock(), blockchainStorage, metricsSystem);
+        DefaultBlockchain.createMutable(
+            genesisState.getBlock(), blockchainStorage, metricsSystem, reorgLoggingThreshold);
 
     final WorldStateArchive worldStateArchive =
         new WorldStateArchive(worldStateStorage, preimageStorage);

ethereum/core/src/main/java/org/hyperledger/besu/ethereum/chain/DefaultBlockchain.java

@@ -17,6 +17,7 @@ package org.hyperledger.besu.ethereum.chain;
 import static com.google.common.base.Preconditions.checkArgument;
 import static com.google.common.base.Preconditions.checkNotNull;
 import static java.util.Collections.emptyList;
+import static java.util.stream.Collectors.joining;
 import static java.util.stream.Collectors.toList;
 
 import org.hyperledger.besu.ethereum.core.Block;
@@ -47,13 +48,17 @@ import java.util.stream.Stream;
 
 import com.google.common.annotations.VisibleForTesting;
 import com.google.common.collect.Lists;
+import com.google.common.collect.Streams;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
 
 public class DefaultBlockchain implements MutableBlockchain {
-
+  private static final Logger LOG = LogManager.getLogger();
   protected final BlockchainStorage blockchainStorage;
 
   private final Subscribers<BlockAddedObserver> blockAddedObservers = Subscribers.create();
   private final Subscribers<ChainReorgObserver> blockReorgObservers = Subscribers.create();
+  private final long reorgLoggingThreshold;
 
   private volatile BlockHeader chainHeader;
   private volatile Difficulty totalDifficulty;
@@ -63,7 +68,8 @@ public class DefaultBlockchain implements MutableBlockchain {
   private DefaultBlockchain(
       final Optional<Block> genesisBlock,
       final BlockchainStorage blockchainStorage,
-      final MetricsSystem metricsSystem) {
+      final MetricsSystem metricsSystem,
+      final long reorgLoggingThreshold) {
     checkNotNull(genesisBlock);
     checkNotNull(blockchainStorage);
     checkNotNull(metricsSystem);
@@ -118,21 +124,27 @@ public class DefaultBlockchain implements MutableBlockchain {
         "chain_head_ommer_count",
         "Number of ommers in the current chain head block",
         () -> chainHeadOmmerCount);
+    this.reorgLoggingThreshold = reorgLoggingThreshold;
   }
 
   public static MutableBlockchain createMutable(
       final Block genesisBlock,
       final BlockchainStorage blockchainStorage,
-      final MetricsSystem metricsSystem) {
+      final MetricsSystem metricsSystem,
+      final long reorgLoggingThreshold) {
     checkNotNull(genesisBlock);
-    return new DefaultBlockchain(Optional.of(genesisBlock), blockchainStorage, metricsSystem);
+    return new DefaultBlockchain(
+        Optional.of(genesisBlock), blockchainStorage, metricsSystem, reorgLoggingThreshold);
   }
 
   public static Blockchain create(
-      final BlockchainStorage blockchainStorage, final MetricsSystem metricsSystem) {
+      final BlockchainStorage blockchainStorage,
+      final MetricsSystem metricsSystem,
+      final long reorgLoggingThreshold) {
     checkArgument(
         validateStorageNonEmpty(blockchainStorage), "Cannot create Blockchain from empty storage");
-    return new DefaultBlockchain(Optional.empty(), blockchainStorage, metricsSystem);
+    return new DefaultBlockchain(
+        Optional.empty(), blockchainStorage, metricsSystem, reorgLoggingThreshold);
   }
 
   private static boolean validateStorageNonEmpty(final BlockchainStorage blockchainStorage) {
@@ -377,6 +389,7 @@ public class DefaultBlockchain implements MutableBlockchain {
       currentNewChainWithReceipts = getParentBlockWithReceipts(currentNewChainWithReceipts);
       currentOldChainWithReceipts = getParentBlockWithReceipts(currentOldChainWithReceipts);
     }
+    final BlockWithReceipts commonAncestorWithReceipts = currentNewChainWithReceipts;
 
     // Update indexed transactions
     newTransactions.forEach(
@@ -398,6 +411,9 @@ public class DefaultBlockchain implements MutableBlockchain {
             .findAny();
     parentFork.ifPresent(forks::remove);
     updater.setForkHeads(forks);
+
+    maybeLogReorg(newChainHeadWithReceipts, oldChainWithReceipts, commonAncestorWithReceipts);
+
     return BlockAddedEvent.createForChainReorg(
         newChainHeadWithReceipts.getBlock(),
         newTransactions.values().stream().flatMap(Collection::stream).collect(toList()),
@@ -408,6 +424,35 @@ public class DefaultBlockchain implements MutableBlockchain {
         currentNewChainWithReceipts.getBlock().getHash());
   }
 
+  private void maybeLogReorg(
+      final BlockWithReceipts newChainHeadWithReceipts,
+      final BlockWithReceipts oldChainWithReceipts,
+      final BlockWithReceipts commonAncestorWithReceipts) {
+    if (newChainHeadWithReceipts.getNumber() - commonAncestorWithReceipts.getNumber()
+            > reorgLoggingThreshold
+        || oldChainWithReceipts.getNumber() - commonAncestorWithReceipts.getNumber()
+            > reorgLoggingThreshold) {
+      LOG.warn(
+          "Chain Reorganization +{} new / -{} old\n{}",
+          () -> newChainHeadWithReceipts.getNumber() - commonAncestorWithReceipts.getNumber(),
+          () -> oldChainWithReceipts.getNumber() - commonAncestorWithReceipts.getNumber(),
+          () ->
+              Streams.zip(
+                      Stream.of("Old", "New", "Ancestor"),
+                      Stream.of(
+                              oldChainWithReceipts,
+                              newChainHeadWithReceipts,
+                              commonAncestorWithReceipts)
+                          .map(
+                              blockWithReceipts ->
+                                  String.format(
+                                      "hash: %s, height: %s",
+                                      blockWithReceipts.getHash(), blockWithReceipts.getNumber())),
+                      (label, values) -> String.format("%10s - %s", label, values))
+                  .collect(joining("\n")));
+    }
+  }
+
   @Override
   public boolean rewindToBlock(final long blockNumber) {
     final Optional<Hash> blockHash = blockchainStorage.getBlockHash(blockNumber);

ethereum/core/src/test-support/java/org/hyperledger/besu/ethereum/core/ExecutionContextTestFixture.java

@@ -55,7 +55,8 @@ public class ExecutionContextTestFixture {
             genesis,
             new KeyValueStoragePrefixedKeyBlockchainStorage(
                 keyValueStorage, new MainnetBlockHeaderFunctions()),
-            new NoOpMetricsSystem());
+            new NoOpMetricsSystem(),
+            0);
     this.stateArchive = createInMemoryWorldStateArchive();
     this.protocolSchedule = protocolSchedule;
     this.protocolContext = new ProtocolContext(blockchain, stateArchive, null);

ethereum/core/src/test-support/java/org/hyperledger/besu/ethereum/core/InMemoryStorageProvider.java

@@ -46,7 +46,8 @@ public class InMemoryStorageProvider implements StorageProvider {
     return DefaultBlockchain.createMutable(
         genesisBlock,
         new KeyValueStoragePrefixedKeyBlockchainStorage(keyValueStorage, blockHeaderFunctions),
-        new NoOpMetricsSystem());
+        new NoOpMetricsSystem(),
+        0);
   }
 
   public static WorldStateArchive createInMemoryWorldStateArchive() {

ethereum/core/src/test/java/org/hyperledger/besu/ethereum/chain/DefaultBlockchainTest.java

@@ -164,7 +164,8 @@ public class DefaultBlockchainTest {
     final Blockchain blockchain =
         DefaultBlockchain.create(
             createStorage(kvStore),
-            PrometheusMetricsSystem.init(MetricsConfiguration.builder().enabled(true).build()));
+            PrometheusMetricsSystem.init(MetricsConfiguration.builder().enabled(true).build()),
+            0);
 
     for (int i = 0; i < blocks.size(); i++) {
       assertBlockDataIsStored(blockchain, blocks.get(i), blockReceipts.get(i));
@@ -948,10 +949,10 @@ public class DefaultBlockchainTest {
       final KeyValueStorage kvStore, final Block genesisBlock) {
     return (DefaultBlockchain)
         DefaultBlockchain.createMutable(
-            genesisBlock, createStorage(kvStore), new NoOpMetricsSystem());
+            genesisBlock, createStorage(kvStore), new NoOpMetricsSystem(), 0);
   }
 
   private Blockchain createBlockchain(final KeyValueStorage kvStore) {
-    return DefaultBlockchain.create(createStorage(kvStore), new NoOpMetricsSystem());
+    return DefaultBlockchain.create(createStorage(kvStore), new NoOpMetricsSystem(), 0);
   }
 }

ethereum/core/src/test/java/org/hyperledger/besu/ethereum/worldstate/PrunerTest.java

@@ -62,7 +62,7 @@ public class PrunerTest {
         new KeyValueStoragePrefixedKeyBlockchainStorage(
             new InMemoryKeyValueStorage(), new MainnetBlockHeaderFunctions());
     final MutableBlockchain blockchain =
-        DefaultBlockchain.createMutable(genesisBlock, blockchainStorage, metricsSystem);
+        DefaultBlockchain.createMutable(genesisBlock, blockchainStorage, metricsSystem, 0);
 
     final Pruner pruner =
         new Pruner(markSweepPruner, blockchain, new PrunerConfiguration(0, 1), mockExecutorService);
@@ -83,7 +83,7 @@ public class PrunerTest {
         new KeyValueStoragePrefixedKeyBlockchainStorage(
             new InMemoryKeyValueStorage(), new MainnetBlockHeaderFunctions());
     final MutableBlockchain blockchain =
-        DefaultBlockchain.createMutable(genesisBlock, blockchainStorage, metricsSystem);
+        DefaultBlockchain.createMutable(genesisBlock, blockchainStorage, metricsSystem, 0);
 
     final Pruner pruner =
         new Pruner(markSweepPruner, blockchain, new PrunerConfiguration(1, 2), mockExecutorService);
@@ -109,7 +109,7 @@ public class PrunerTest {
         new KeyValueStoragePrefixedKeyBlockchainStorage(
             new InMemoryKeyValueStorage(), new MainnetBlockHeaderFunctions());
     final MutableBlockchain blockchain =
-        DefaultBlockchain.createMutable(genesisBlock, blockchainStorage, metricsSystem);
+        DefaultBlockchain.createMutable(genesisBlock, blockchainStorage, metricsSystem, 0);
 
     // start pruner so it can start handling block added events
     final Pruner pruner =
@@ -179,7 +179,7 @@ public class PrunerTest {
         new KeyValueStoragePrefixedKeyBlockchainStorage(
             new InMemoryKeyValueStorage(), new MainnetBlockHeaderFunctions());
     final MutableBlockchain blockchain =
-        DefaultBlockchain.createMutable(genesisBlock, blockchainStorage, metricsSystem);
+        DefaultBlockchain.createMutable(genesisBlock, blockchainStorage, metricsSystem, 0);
 
     final Pruner pruner =
         new Pruner(markSweepPruner, blockchain, new PrunerConfiguration(0, 1), mockExecutorService);

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/tasks/DetermineCommonAncestorTask.java

@@ -68,7 +68,10 @@ public class DetermineCommonAncestorTask extends AbstractEthTask<BlockHeader> {
     this.headerRequestSize = headerRequestSize;
     this.metricsSystem = metricsSystem;
 
-    maximumPossibleCommonAncestorNumber = protocolContext.getBlockchain().getChainHeadBlockNumber();
+    maximumPossibleCommonAncestorNumber =
+        Math.min(
+            protocolContext.getBlockchain().getChainHeadBlockNumber(),
+            peer.chainState().getEstimatedHeight());
     minimumPossibleCommonAncestorNumber = BlockHeader.GENESIS_BLOCK_NUMBER;
     commonAncestorCandidate =
         protocolContext.getBlockchain().getBlockHeader(BlockHeader.GENESIS_BLOCK_NUMBER).get();

ethereum/eth/src/test/java/org/hyperledger/besu/ethereum/eth/sync/fullsync/FullSyncTargetManagerTest.java

@@ -93,7 +93,7 @@ public class FullSyncTargetManagerTest {
     when(localWorldState.isWorldStateAvailable(localBlockchain.getChainHeadHeader().getStateRoot()))
         .thenReturn(true);
     final RespondingEthPeer bestPeer =
-        EthProtocolManagerTestUtil.createPeer(ethProtocolManager, Difficulty.MAX_VALUE, 1);
+        EthProtocolManagerTestUtil.createPeer(ethProtocolManager, Difficulty.MAX_VALUE, 4);
 
     final CompletableFuture<SyncTarget> result = syncTargetManager.findSyncTarget(Optional.empty());
     bestPeer.respond(responder);

ethereum/evmtool/src/main/java/org/hyperledger/besu/evmtool/BlockchainModule.java

@@ -49,7 +49,7 @@ public class BlockchainModule {
       @Named("GenesisBlock") final Block genesisBlock,
       final BlockchainStorage blockchainStorage,
       final MetricsSystem metricsSystem) {
-    return DefaultBlockchain.createMutable(genesisBlock, blockchainStorage, metricsSystem);
+    return DefaultBlockchain.createMutable(genesisBlock, blockchainStorage, metricsSystem, 0);
   }
 
   @Provides

ethereum/retesteth/src/main/java/org/hyperledger/besu/ethereum/retesteth/RetestethContext.java

@@ -207,7 +207,8 @@ public class RetestethContext {
     return DefaultBlockchain.createMutable(
         genesisBlock,
         new KeyValueStoragePrefixedKeyBlockchainStorage(keyValueStorage, blockHeaderFunctions),
-        new NoOpMetricsSystem());
+        new NoOpMetricsSystem(),
+        0);
   }
 
   public ProtocolSchedule getProtocolSchedule() {