diff --git a/CHANGELOG.md b/CHANGELOG.md index c37cd834112..970e5103e5f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -38,6 +38,7 @@ ### Bug fixes - Fix the way an advertised host configured with `--p2p-host` is treated when communicating with the originator of a PING packet [#6225](https://github.com/hyperledger/besu/pull/6225) - Fix `poa-block-txs-selection-max-time` option that was inadvertently reset to its default after being configured [#6444](https://github.com/hyperledger/besu/pull/6444) +- Fix for tx incorrectly discarded when there is a timeout during block creation [#6563](https://github.com/hyperledger/besu/pull/6563) ### Download Links diff --git a/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/txselection/BlockTransactionSelector.java b/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/txselection/BlockTransactionSelector.java index 26ac79ef384..b37cff7e43a 100644 --- a/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/txselection/BlockTransactionSelector.java +++ b/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/txselection/BlockTransactionSelector.java @@ -383,33 +383,11 @@ 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; - } // 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 return handleTransactionNotSelected( - evaluationContext, timeoutSelectionResult, txWorldStateUpdater); + evaluationContext, BLOCK_SELECTION_TIMEOUT, txWorldStateUpdater); } pluginTransactionSelector.onTransactionSelected(evaluationContext, processingResult); @@ -437,17 +415,47 @@ private TransactionSelectionResult handleTransactionNotSelected( final var pendingTransaction = evaluationContext.getPendingTransaction(); - transactionSelectionResults.updateNotSelected( - evaluationContext.getTransaction(), selectionResult); - pluginTransactionSelector.onTransactionNotSelected(evaluationContext, selectionResult); + // check if this tx took too much to evaluate, and in case remove it from the pool + final TransactionSelectionResult actualResult = + isTimeout.get() + ? 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 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()::getHash) + .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( diff --git a/ethereum/blockcreation/src/test/java/org/hyperledger/besu/ethereum/blockcreation/AbstractBlockTransactionSelectorTest.java b/ethereum/blockcreation/src/test/java/org/hyperledger/besu/ethereum/blockcreation/AbstractBlockTransactionSelectorTest.java index e593569ff28..50879b26766 100644 --- a/ethereum/blockcreation/src/test/java/org/hyperledger/besu/ethereum/blockcreation/AbstractBlockTransactionSelectorTest.java +++ b/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> inTime = () -> invocation -> SELECTED; + + final BiFunction> 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 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(); + 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 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) {