Fix for tx incorrectly discarded when there is a timeout during block creation

CHANGELOG.md

@@ -1,5 +1,16 @@
 # Changelog
 
+## 24.1.3-SNAPSHOT
+
+### Breaking Changes
+
+### Deprecations
+
+### Additions and Improvements
+
+### Bug fixes
+- Fix for tx incorrectly discarded when there is a timeout during block creation [#6563](https://github.com/hyperledger/besu/pull/6563)
+
 ## 24.1.2-SNAPSHOT
 
 ### Breaking Changes
@@ -9,7 +20,6 @@
 - `--Xfilter-on-enr-fork-id` has been removed. To disable the feature use `--filter-on-enr-fork-id=false`.
 - `--engine-jwt-enabled` has been removed. Use `--engine-jwt-disabled` instead. [#6491](https://github.com/hyperledger/besu/pull/6491)
 
-
 ### Deprecations
 - X_SNAP and X_CHECKPOINT are marked for deprecation and will be removed in 24.4.0 in favor of SNAP and CHECKPOINT [#6405](https://github.com/hyperledger/besu/pull/6405)
 - `--Xsnapsync-synchronizer-flat-db-healing-enabled` is deprecated (always enabled). [#6499](https://github.com/hyperledger/besu/pull/6499)

ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/txselection/BlockTransactionSelector.java

@@ -383,28 +383,12 @@ private TransactionSelectionResult handleTransactionSelected(
     if (tooLate) {
       // even if this tx passed all the checks, it is too late to include it in this block,
       // so we need to treat it as not selected
-      final var evaluationTimer = evaluationContext.getEvaluationTimer();
 
       // check if this tx took too much to evaluate, and in case remove it from the pool
-      final TransactionSelectionResult timeoutSelectionResult;
-      if (evaluationTimer.elapsed(TimeUnit.MILLISECONDS) > blockTxsSelectionMaxTime) {
-        LOG.atWarn()
-            .setMessage(
-                "Transaction {} is too late for inclusion, evaluated in {} that is over the max limit of {}ms"
-                    + ", removing it from the pool")
-            .addArgument(transaction::toTraceLog)
-            .addArgument(evaluationTimer)
-            .addArgument(blockTxsSelectionMaxTime)
-            .log();
-        timeoutSelectionResult = TX_EVALUATION_TOO_LONG;
-      } else {
-        LOG.atTrace()
-            .setMessage("Transaction {} is too late for inclusion")
-            .addArgument(transaction::toTraceLog)
-            .addArgument(evaluationTimer)
-            .log();
-        timeoutSelectionResult = BLOCK_SELECTION_TIMEOUT;
-      }
+      final TransactionSelectionResult timeoutSelectionResult =
+          transactionTookTooLong(evaluationContext)
+              ? TX_EVALUATION_TOO_LONG
+              : BLOCK_SELECTION_TIMEOUT;
 
       // do not rely on the presence of this result, since by the time it is added, the code
       // reading it could have been already executed by another thread
@@ -437,17 +421,51 @@ private TransactionSelectionResult handleTransactionNotSelected(
 
     final var pendingTransaction = evaluationContext.getPendingTransaction();
 
-    transactionSelectionResults.updateNotSelected(
-        evaluationContext.getTransaction(), selectionResult);
-    pluginTransactionSelector.onTransactionNotSelected(evaluationContext, selectionResult);
+    final TransactionSelectionResult actualResult =
+        isTimeout.get() && !wasTimeout(selectionResult)
+            ? transactionTookTooLong(evaluationContext)
+                ? TX_EVALUATION_TOO_LONG
+                : BLOCK_SELECTION_TIMEOUT
+            : selectionResult;
+
+    transactionSelectionResults.updateNotSelected(evaluationContext.getTransaction(), actualResult);
+    pluginTransactionSelector.onTransactionNotSelected(evaluationContext, actualResult);
     LOG.atTrace()
-        .setMessage("Not selected {} for block creation with result {}, evaluated in {}")
+        .setMessage(
+            "Not selected {} for block creation with result {} (original result {}), evaluated in {}")
         .addArgument(pendingTransaction::toTraceLog)
+        .addArgument(actualResult)
         .addArgument(selectionResult)
         .addArgument(evaluationContext.getEvaluationTimer())
         .log();
 
-    return selectionResult;
+    return actualResult;
+  }
+
+  private boolean wasTimeout(final TransactionSelectionResult selectionResult) {
+    return selectionResult.equals(TX_EVALUATION_TOO_LONG)
+        || selectionResult.equals(BLOCK_SELECTION_TIMEOUT);
+  }
+
+  private boolean transactionTookTooLong(final TransactionEvaluationContext evaluationContext) {
+    final var evaluationTimer = evaluationContext.getEvaluationTimer();
+    if (evaluationTimer.elapsed(TimeUnit.MILLISECONDS) > blockTxsSelectionMaxTime) {
+      LOG.atWarn()
+          .setMessage(
+              "Transaction {} is too late for inclusion, evaluated in {} that is over the max limit of {}ms"
+                  + ", removing it from the pool")
+          .addArgument(evaluationContext.getPendingTransaction()::toTraceLog)
+          .addArgument(evaluationTimer)
+          .addArgument(blockTxsSelectionMaxTime)
+          .log();
+      return true;
+    }
+    LOG.atTrace()
+        .setMessage("Transaction {} is too late for inclusion")
+        .addArgument(evaluationContext.getPendingTransaction()::toTraceLog)
+        .log();
+
+    return false;
   }
 
   private TransactionSelectionResult handleTransactionNotSelected(

ethereum/blockcreation/src/test/java/org/hyperledger/besu/ethereum/blockcreation/AbstractBlockTransactionSelectorTest.java

@@ -18,6 +18,7 @@
 import static org.assertj.core.api.Assertions.entry;
 import static org.awaitility.Awaitility.await;
 import static org.hyperledger.besu.ethereum.core.MiningParameters.DEFAULT_NON_POA_BLOCK_TXS_SELECTION_MAX_TIME;
+import static org.hyperledger.besu.ethereum.transaction.TransactionInvalidReason.UPFRONT_COST_EXCEEDS_BALANCE;
 import static org.hyperledger.besu.plugin.data.TransactionSelectionResult.BLOCK_SELECTION_TIMEOUT;
 import static org.hyperledger.besu.plugin.data.TransactionSelectionResult.PRIORITY_FEE_PER_GAS_BELOW_CURRENT_MIN;
 import static org.hyperledger.besu.plugin.data.TransactionSelectionResult.SELECTED;
@@ -90,6 +91,7 @@
 import java.time.Instant;
 import java.util.ArrayList;
 import java.util.Arrays;
+import java.util.HashMap;
 import java.util.List;
 import java.util.Optional;
 import java.util.concurrent.CompletableFuture;
@@ -1026,6 +1028,152 @@ private void internalBlockSelectionTimeoutSimulation(
         .isEqualTo(isLongProcessingTxDropped ? true : false);
   }
 
+  @ParameterizedTest
+  @MethodSource("subsetOfPendingTransactionsIncludedWhenTxSelectionMaxTimeIsOver")
+  public void subsetOfInvalidPendingTransactionsIncludedWhenTxSelectionMaxTimeIsOver(
+      final boolean isPoa,
+      final boolean preProcessingTooLate,
+      final boolean processingTooLate,
+      final boolean postProcessingTooLate) {
+
+    internalBlockSelectionTimeoutSimulationInvalidTxs(
+        isPoa,
+        preProcessingTooLate,
+        processingTooLate,
+        postProcessingTooLate,
+        500,
+        BLOCK_SELECTION_TIMEOUT,
+        false,
+        UPFRONT_COST_EXCEEDS_BALANCE);
+  }
+
+  @ParameterizedTest
+  @MethodSource("subsetOfPendingTransactionsIncludedWhenTxSelectionMaxTimeIsOver")
+  public void invalidPendingTransactionsThatTakesTooLongToEvaluateIsDroppedFromThePool(
+      final boolean isPoa,
+      final boolean preProcessingTooLate,
+      final boolean processingTooLate,
+      final boolean postProcessingTooLate) {
+
+    internalBlockSelectionTimeoutSimulationInvalidTxs(
+        isPoa,
+        preProcessingTooLate,
+        processingTooLate,
+        postProcessingTooLate,
+        900,
+        TX_EVALUATION_TOO_LONG,
+        true,
+        UPFRONT_COST_EXCEEDS_BALANCE);
+  }
+
+  private void internalBlockSelectionTimeoutSimulationInvalidTxs(
+      final boolean isPoa,
+      final boolean preProcessingTooLate,
+      final boolean processingTooLate,
+      final boolean postProcessingTooLate,
+      final long longProcessingTxTime,
+      final TransactionSelectionResult longProcessingTxResult,
+      final boolean isLongProcessingTxDropped,
+      final TransactionInvalidReason txInvalidReason) {
+
+    final int txCount = 3;
+    final long fastProcessingTxTime = 200;
+    final var invalidSelectionResult = TransactionSelectionResult.invalid(txInvalidReason.name());
+
+    final Supplier<Answer<TransactionSelectionResult>> inTime = () -> invocation -> SELECTED;
+
+    final BiFunction<Transaction, Long, Answer<TransactionSelectionResult>> tooLate =
+        (p, t) ->
+            invocation -> {
+              final org.hyperledger.besu.ethereum.blockcreation.txselection
+                      .TransactionEvaluationContext
+                  ctx = invocation.getArgument(0);
+              if (ctx.getTransaction().equals(p)) {
+                Thread.sleep(t);
+              } else {
+                Thread.sleep(fastProcessingTxTime);
+              }
+              return invalidSelectionResult;
+            };
+
+    final ProcessableBlockHeader blockHeader = createBlock(301_000);
+    final Address miningBeneficiary = AddressHelpers.ofValue(1);
+    final int poaGenesisBlockPeriod = 1;
+    final int blockTxsSelectionMaxTime = 750;
+
+    final List<Transaction> transactionsToInject = new ArrayList<>(txCount);
+    for (int i = 0; i < txCount - 1; i++) {
+      final Transaction tx = createTransaction(i, Wei.of(7), 100_000);
+      transactionsToInject.add(tx);
+      if (processingTooLate) {
+        ensureTransactionIsInvalid(tx, txInvalidReason, fastProcessingTxTime);
+      } else {
+        ensureTransactionIsValid(tx);
+      }
+    }
+
+    final Transaction lateTx = createTransaction(2, Wei.of(7), 100_000);
+    transactionsToInject.add(lateTx);
+    if (processingTooLate) {
+      ensureTransactionIsInvalid(lateTx, txInvalidReason, longProcessingTxTime);
+    } else {
+      ensureTransactionIsValid(lateTx);
+    }
+
+    PluginTransactionSelector transactionSelector = mock(PluginTransactionSelector.class);
+    when(transactionSelector.evaluateTransactionPreProcessing(any()))
+        .thenAnswer(
+            preProcessingTooLate ? tooLate.apply(lateTx, longProcessingTxTime) : inTime.get());
+
+    when(transactionSelector.evaluateTransactionPostProcessing(any(), any()))
+        .thenAnswer(
+            postProcessingTooLate ? tooLate.apply(lateTx, longProcessingTxTime) : inTime.get());
+
+    final PluginTransactionSelectorFactory transactionSelectorFactory =
+        mock(PluginTransactionSelectorFactory.class);
+    when(transactionSelectorFactory.create()).thenReturn(transactionSelector);
+
+    final BlockTransactionSelector selector =
+        createBlockSelectorAndSetupTxPool(
+            isPoa
+                ? createMiningParameters(
+                    Wei.ZERO,
+                    MIN_OCCUPANCY_100_PERCENT,
+                    poaGenesisBlockPeriod,
+                    PositiveNumber.fromInt(75))
+                : createMiningParameters(
+                    Wei.ZERO,
+                    MIN_OCCUPANCY_100_PERCENT,
+                    PositiveNumber.fromInt(blockTxsSelectionMaxTime)),
+            transactionProcessor,
+            blockHeader,
+            miningBeneficiary,
+            Wei.ZERO,
+            transactionSelectorFactory);
+
+    transactionPool.addRemoteTransactions(transactionsToInject);
+
+    final TransactionSelectionResults results = selector.buildTransactionListForBlock();
+
+    // no tx is selected since all are invalid
+    assertThat(results.getSelectedTransactions()).isEmpty();
+
+    // all txs are not selected so wait until all are evaluated
+    // before checking the results
+    await().until(() -> results.getNotSelectedTransactions().size() == transactionsToInject.size());
+    final var expectedEntries = new HashMap<Transaction, TransactionSelectionResult>();
+    for (int i = 0; i < txCount - 1; i++) {
+      expectedEntries.put(
+          transactionsToInject.get(i), TransactionSelectionResult.invalid(txInvalidReason.name()));
+    }
+    expectedEntries.put(lateTx, longProcessingTxResult);
+    assertThat(results.getNotSelectedTransactions())
+        .containsExactlyInAnyOrderEntriesOf(expectedEntries);
+
+    assertThat(transactionPool.getTransactionByHash(lateTx.getHash()).isEmpty())
+        .isEqualTo(isLongProcessingTxDropped ? true : false);
+  }
+
   private static Stream<Arguments>
       subsetOfPendingTransactionsIncludedWhenTxSelectionMaxTimeIsOver() {
 
@@ -1170,9 +1318,22 @@ protected void ensureTransactionIsValid(
 
   protected void ensureTransactionIsInvalid(
       final Transaction tx, final TransactionInvalidReason invalidReason) {
+    ensureTransactionIsInvalid(tx, invalidReason, 0);
+  }
+
+  protected void ensureTransactionIsInvalid(
+      final Transaction tx,
+      final TransactionInvalidReason invalidReason,
+      final long processingTime) {
     when(transactionProcessor.processTransaction(
             any(), any(), any(), eq(tx), any(), any(), any(), anyBoolean(), any(), any()))
-        .thenReturn(TransactionProcessingResult.invalid(ValidationResult.invalid(invalidReason)));
+        .thenAnswer(
+            invocation -> {
+              if (processingTime > 0) {
+                Thread.sleep(processingTime);
+              }
+              return TransactionProcessingResult.invalid(ValidationResult.invalid(invalidReason));
+            });
   }
 
   private BlockHeader blockHeader(final long number) {