Add more tracing logs to transaction pool

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

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

@@ -14,6 +14,8 @@
  */
 package org.hyperledger.besu.ethereum.blockcreation;
 
+import static org.hyperledger.besu.util.Slf4jLambdaHelper.traceLambda;
+
 import org.hyperledger.besu.datatypes.Address;
 import org.hyperledger.besu.datatypes.Wei;
 import org.hyperledger.besu.ethereum.chain.Blockchain;
@@ -39,6 +41,7 @@
 import java.util.List;
 import java.util.concurrent.CancellationException;
 import java.util.function.Supplier;
+import java.util.stream.Collectors;
 
 import com.google.common.collect.Lists;
 import org.apache.tuweni.bytes.Bytes;
@@ -82,6 +85,12 @@ private void update(
       transactions.add(transaction);
       receipts.add(receipt);
       cumulativeGasUsed += gasUsed;
+      traceLambda(
+          LOG,
+          "New selected transaction {}, total transactions {}, cumulative gas used {}",
+          transaction::toTraceLog,
+          transactions::size,
+          () -> cumulativeGasUsed);
     }
 
     public List<Transaction> getTransactions() {
@@ -95,6 +104,13 @@ public List<TransactionReceipt> getReceipts() {
     public long getCumulativeGasUsed() {
       return cumulativeGasUsed;
     }
+
+    public String toTraceLog() {
+      return "cumulativeGasUsed="
+          + cumulativeGasUsed
+          + ", transactions="
+          + transactions.stream().map(Transaction::toTraceLog).collect(Collectors.joining("; "));
+    }
   }
 
   private final Supplier<Boolean> isCancelled;
@@ -173,8 +189,13 @@ private TransactionSelectionResult evaluateTransaction(final Transaction transac
     }
 
     if (transactionTooLargeForBlock(transaction)) {
-      LOG.trace("{} too large to select for block creation", transaction);
+      traceLambda(
+          LOG, "Transaction {} too large to select for block creation", transaction::toTraceLog);
       if (blockOccupancyAboveThreshold()) {
+        traceLambda(
+            LOG,
+            "Block occupancy above threshold, completing operation, result {}",
+            transactionSelectionResult::toTraceLog);
         return TransactionSelectionResult.COMPLETE_OPERATION;
       } else {
         return TransactionSelectionResult.CONTINUE;
@@ -212,7 +233,7 @@ private TransactionSelectionResult evaluateTransaction(final Transaction transac
             validationResult.getErrorMessage(),
             processableBlockHeader.getParentHash().toHexString(),
             transaction.getHash().toHexString());
-        return transactionSelectionResultForInvalidResult(validationResult);
+        return transactionSelectionResultForInvalidResult(transaction, validationResult);
       } else {
         // valid GoQuorum private tx, we need to hand craft the receipt and increment the nonce
         effectiveResult = publicResultForWhenWeHaveAPrivateTransaction(transaction);
@@ -233,23 +254,34 @@ private TransactionSelectionResult evaluateTransaction(final Transaction transac
 
     if (!effectiveResult.isInvalid()) {
       worldStateUpdater.commit();
-      LOG.trace("Selected {} for block creation", transaction);
+      traceLambda(LOG, "Selected {} for block creation", transaction::toTraceLog);
       updateTransactionResultTracking(transaction, effectiveResult);
     } else {
-      return transactionSelectionResultForInvalidResult(effectiveResult.getValidationResult());
+      return transactionSelectionResultForInvalidResult(
+          transaction, effectiveResult.getValidationResult());
     }
     return TransactionSelectionResult.CONTINUE;
   }
 
   private TransactionSelectionResult transactionSelectionResultForInvalidResult(
+      final Transaction transaction,
       final ValidationResult<TransactionInvalidReason> invalidReasonValidationResult) {
     // If the transaction has an incorrect nonce, leave it in the pool and continue
     if (invalidReasonValidationResult
         .getInvalidReason()
         .equals(TransactionInvalidReason.INCORRECT_NONCE)) {
+      traceLambda(
+          LOG,
+          "Incorrect nonce for transaction {} keeping it in the pool",
+          transaction::toTraceLog);
       return TransactionSelectionResult.CONTINUE;
     }
     // If the transaction was invalid for any other reason, delete it, and continue.
+    traceLambda(
+        LOG,
+        "Delete invalid transaction {}, reason {}",
+        transaction::toTraceLog,
+        invalidReasonValidationResult::getInvalidReason);
     return TransactionSelectionResult.DELETE_TRANSACTION_AND_CONTINUE;
   }
 
@@ -318,6 +350,13 @@ private boolean transactionTooLargeForBlock(final Transaction transaction) {
   private boolean blockOccupancyAboveThreshold() {
     final double gasAvailable = processableBlockHeader.getGasLimit();
     final double gasUsed = transactionSelectionResult.getCumulativeGasUsed();
-    return (gasUsed / gasAvailable) >= minBlockOccupancyRatio;
+    final double occupancyRatio = gasUsed / gasAvailable;
+    LOG.trace(
+        "Min block occupancy ratio {}, gas used {}, available {}, used/available {}",
+        minBlockOccupancyRatio,
+        gasUsed,
+        gasAvailable,
+        occupancyRatio);
+    return occupancyRatio >= minBlockOccupancyRatio;
   }
 }

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

@@ -902,6 +902,23 @@ public String toString() {
     return sb.append("}").toString();
   }
 
+  public String toTraceLog() {
+    final StringBuilder sb = new StringBuilder();
+    sb.append(isContractCreation() ? "ContractCreation" : "MessageCall").append(", ");
+    sb.append(getSender()).append(", ");
+    sb.append(getType()).append(", ");
+    sb.append(getNonce()).append(", ");
+    getGasPrice().ifPresent(gasPrice -> sb.append(gasPrice.toBigInteger()).append(", "));
+    if (getMaxPriorityFeePerGas().isPresent() && getMaxFeePerGas().isPresent()) {
+      sb.append(getMaxPriorityFeePerGas().map(Wei::toBigInteger).get()).append(", ");
+      sb.append(getMaxFeePerGas().map(Wei::toBigInteger).get()).append(", ");
+    }
+    sb.append(getGasLimit()).append(", ");
+    sb.append(getValue().toBigInteger()).append(", ");
+    if (getTo().isPresent()) sb.append(getTo().get()).append(", ");
+    return sb.append("}").toString();
+  }
+
   public Optional<Address> contractAddress() {
     if (isContractCreation()) {
       return Optional.of(Address.contractAddress(getSender(), getNonce()));

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/transactions/TransactionPool.java

@@ -48,10 +48,10 @@
 import org.hyperledger.besu.plugin.services.metrics.Counter;
 import org.hyperledger.besu.plugin.services.metrics.LabelledMetric;
 
+import java.util.ArrayList;
 import java.util.Collection;
-import java.util.HashSet;
+import java.util.List;
 import java.util.Optional;
-import java.util.Set;
 
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
@@ -139,35 +139,51 @@ private boolean effectiveGasPriceIsAboveConfiguredMinGasPrice(final Transaction
   }
 
   public void addRemoteTransactions(final Collection<Transaction> transactions) {
-    final Set<Transaction> addedTransactions = new HashSet<>(transactions.size());
+    final List<Transaction> addedTransactions = new ArrayList<>(transactions.size());
+    LOG.trace("Adding {} remote transactions", transactions.size());
     for (final Transaction transaction : transactions) {
       if (pendingTransactions.containsTransaction(transaction.getHash())) {
+        traceLambda(LOG, "Discard already present transaction {}", transaction::toTraceLog);
         // We already have this transaction, don't even validate it.
         duplicateTransactionCounter.labels(REMOTE).inc();
         continue;
       }
       final Wei transactionGasPrice = minTransactionGasPrice(transaction);
       if (transactionGasPrice.compareTo(miningParameters.getMinTransactionGasPrice()) < 0) {
+        traceLambda(
+            LOG,
+            "Discard transaction {} below min gas price {}",
+            transaction::toTraceLog,
+            miningParameters::getMinTransactionGasPrice);
         continue;
       }
       final ValidationResult<TransactionInvalidReason> validationResult =
           validateRemoteTransaction(transaction);
       if (validationResult.isValid()) {
         final boolean added = pendingTransactions.addRemoteTransaction(transaction);
         if (added) {
+          traceLambda(LOG, "Added remote transaction {}", transaction::toTraceLog);
           addedTransactions.add(transaction);
         } else {
+          traceLambda(LOG, "Duplicate remote transaction {}", transaction::toTraceLog);
           duplicateTransactionCounter.labels(REMOTE).inc();
         }
       } else {
-        LOG.trace(
-            "Validation failed ({}) for transaction {}. Discarding.",
-            validationResult.getInvalidReason(),
-            transaction);
+        traceLambda(
+            LOG,
+            "Discard invalid transaction {}, reason {}",
+            transaction::toTraceLog,
+            validationResult::getInvalidReason);
       }
     }
     if (!addedTransactions.isEmpty()) {
       transactionBroadcaster.onTransactionsAdded(addedTransactions);
+      traceLambda(
+          LOG,
+          "Added {} transactions to the pool, current pool size {}, content {}",
+          addedTransactions::size,
+          pendingTransactions::size,
+          pendingTransactions::toTraceLog);
     }
   }
 
@@ -189,9 +205,14 @@ public void unsubscribeDroppedTransactions(final long id) {
 
   @Override
   public void onBlockAdded(final BlockAddedEvent event) {
+    LOG.trace("Block added event {}", event);
     event.getAddedTransactions().forEach(pendingTransactions::transactionAddedToBlock);
     pendingTransactions.manageBlockAdded(event.getBlock());
-    addRemoteTransactions(event.getRemovedTransactions());
+    var readdTransactions = event.getRemovedTransactions();
+    if (!readdTransactions.isEmpty()) {
+      LOG.trace("Readding {} transactions from a block event", readdTransactions.size());
+      addRemoteTransactions(readdTransactions);
+    }
   }
 
   private MainnetTransactionValidator getTransactionValidator() {
@@ -222,7 +243,7 @@ private ValidationResult<TransactionInvalidReason> validateTransaction(
       traceLambda(
           LOG,
           "rejecting transaction {} due to chain head not available yet",
-          () -> transaction.getHash());
+          transaction::getHash);
       return ValidationResult.invalid(CHAIN_HEAD_NOT_AVAILABLE);
     }
 

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/transactions/TransactionsForSenderInfo.java

@@ -23,6 +23,7 @@
 import java.util.Optional;
 import java.util.OptionalLong;
 import java.util.TreeMap;
+import java.util.stream.Collectors;
 import java.util.stream.Stream;
 
 public class TransactionsForSenderInfo {
@@ -97,4 +98,15 @@ public Stream<TransactionInfo> streamTransactionInfos() {
   public TransactionInfo getTransactionInfoForNonce(final long nonce) {
     return transactionsInfos.get(nonce);
   }
+
+  public String toTraceLog() {
+    return "{"
+        + "transactions "
+        + transactionsInfos.entrySet().stream()
+            .map(e -> "(" + e.getKey() + ")" + e.getValue().toTraceLog())
+            .collect(Collectors.joining("; "))
+        + ", nextGap "
+        + nextGap
+        + '}';
+  }
 }