moved some logs to trace level (#6207)

* moved some logs to trace level

* shortNodeId

* Apply suggestions from code review

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

Signed-off-by: Sally MacFarlane <macfarla.github@gmail.com>

---------

Signed-off-by: Sally MacFarlane <macfarla.github@gmail.com>
Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>
Co-authored-by: Fabio Di Fabio <fabio.difabio@consensys.net>

ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/query/cache/TransactionLogBloomCacher.java

@@ -159,7 +159,10 @@ public class TransactionLogBloomCacher {
         return;
       }
       final long blockNumber = blockHeader.getNumber();
-      LOG.debug("Caching logs bloom for block {}.", "0x" + Long.toHexString(blockNumber));
+      LOG.atDebug()
+          .setMessage("Caching logs bloom for block {}")
+          .addArgument(() -> "0x" + Long.toHexString(blockNumber))
+          .log();
       final File cacheFile = reusedCacheFile.orElse(calculateCacheFileName(blockNumber, cacheDir));
       if (cacheFile.exists()) {
         try {

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthPeer.java

@@ -210,16 +210,20 @@ public class EthPeer implements Comparable<EthPeer> {
   }
 
   public void recordRequestTimeout(final int requestCode) {
-    LOG.debug("Timed out while waiting for response from peer {}", this.getShortNodeId());
+    LOG.atDebug()
+        .setMessage("Timed out while waiting for response from peer {}...")
+        .addArgument(this::getShortNodeId)
+        .log();
     LOG.trace("Timed out while waiting for response from peer {}", this);
     reputation.recordRequestTimeout(requestCode).ifPresent(this::disconnect);
   }
 
   public void recordUselessResponse(final String requestType) {
-    LOG.debug(
-        "Received useless response for request type {} from peer {}",
-        requestType,
-        this.getShortNodeId());
+    LOG.atTrace()
+        .setMessage("Received useless response for request type {} from peer {}...")
+        .addArgument(requestType)
+        .addArgument(this::getShortNodeId)
+        .log();
     reputation.recordUselessResponse(System.currentTimeMillis()).ifPresent(this::disconnect);
   }
 

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractGetHeadersFromPeerTask.java

@@ -125,11 +125,11 @@ public abstract class AbstractGetHeadersFromPeerTask
       updatePeerChainState(peer, header);
     }
 
-    LOG.atDebug()
+    LOG.atTrace()
         .setMessage("Received {} of {} headers requested from peer {}...")
-        .addArgument(headersList.size())
+        .addArgument(headersList::size)
         .addArgument(count)
-        .addArgument(peer.getShortNodeId())
+        .addArgument(peer::getShortNodeId)
         .log();
     return Optional.of(headersList);
   }

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractRetryingSwitchingPeerTask.java

@@ -145,7 +145,7 @@ public abstract class AbstractRetryingSwitchingPeerTask<T> extends AbstractRetry
               peer -> {
                 LOG.atDebug()
                     .setMessage(
-                        "Refresh peers disconnecting peer {}. Waiting for better peers. Current {} of max {}")
+                        "Refresh peers disconnecting peer {}... Waiting for better peers. Current {} of max {}")
                     .addArgument(peer::getShortNodeId)
                     .addArgument(peers::peerCount)
                     .addArgument(peers::getMaxPeers)

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/BufferedGetPooledTransactionsFromPeerFetcher.java

@@ -89,10 +89,10 @@ public class BufferedGetPooledTransactionsFromPeerFetcher {
                 transactionTracker.markTransactionsAsSeen(peer, retrievedTransactions);
 
                 LOG.atTrace()
-                    .setMessage("Got {} transactions of {} hashes requested from peer {}")
+                    .setMessage("Got {} transactions of {} hashes requested from peer {}...")
                     .addArgument(retrievedTransactions::size)
                     .addArgument(task.getTransactionHashes()::size)
-                    .addArgument(peer)
+                    .addArgument(peer::getShortNodeId)
                     .log();
 
                 transactionPool.addRemoteTransactions(retrievedTransactions);
@@ -120,8 +120,8 @@ public class BufferedGetPooledTransactionsFromPeerFetcher {
     metrics.incrementAlreadySeenTransactions(metricLabel, alreadySeenCount);
     LOG.atTrace()
         .setMessage(
-            "Transaction hashes to request from peer {}, fresh count {}, already seen count {}")
-        .addArgument(peer)
+            "Transaction hashes to request from peer {}... fresh count {}, already seen count {}")
+        .addArgument(peer::getShortNodeId)
         .addArgument(toRetrieve::size)
         .addArgument(alreadySeenCount)
         .log();

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetBodiesFromPeerTask.java

@@ -93,7 +93,11 @@ public class GetBodiesFromPeerTask extends AbstractPeerRequestTask<List<Block>>
 
     return sendRequestToPeer(
         peer -> {
-          LOG.debug("Requesting {} bodies from peer {}.", blockHashes.size(), peer);
+          LOG.atTrace()
+              .setMessage("Requesting {} bodies from peer {}.")
+              .addArgument(blockHashes.size())
+              .addArgument(peer)
+              .log();
           return peer.getBodies(blockHashes);
         },
         minimumRequiredBlockNumber);
@@ -103,7 +107,7 @@ public class GetBodiesFromPeerTask extends AbstractPeerRequestTask<List<Block>>
   protected Optional<List<Block>> processResponse(
       final boolean streamClosed, final MessageData message, final EthPeer peer) {
     if (streamClosed) {
-      // All outstanding requests have been responded to and we still haven't found the response
+      // All outstanding requests have been responded to, and we still haven't found the response
       // we wanted. It must have been empty or contain data that didn't match.
       peer.recordUselessResponse("bodies");
       return Optional.of(Collections.emptyList());

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetHeadersFromPeerByHashTask.java

@@ -119,11 +119,11 @@ public class GetHeadersFromPeerByHashTask extends AbstractGetHeadersFromPeerTask
   protected PendingPeerRequest sendRequest() {
     return sendRequestToPeer(
         peer -> {
-          LOG.atDebug()
+          LOG.atTrace()
               .setMessage("Requesting {} headers (hash {}...) from peer {}...")
               .addArgument(count)
               .addArgument(referenceHash.slice(0, 6))
-              .addArgument(peer.getShortNodeId())
+              .addArgument(peer::getShortNodeId)
               .log();
           return peer.getHeadersByHash(referenceHash, count, skip, reverse);
         },

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetHeadersFromPeerByNumberTask.java

@@ -77,11 +77,12 @@ public class GetHeadersFromPeerByNumberTask extends AbstractGetHeadersFromPeerTa
   protected PendingPeerRequest sendRequest() {
     return sendRequestToPeer(
         peer -> {
-          LOG.debug(
-              "Requesting {} headers (blockNumber {}) from peer {}.",
-              count,
-              blockNumber,
-              peer.getShortNodeId());
+          LOG.atTrace()
+              .setMessage("Requesting {} headers (blockNumber {}) from peer {}.")
+              .addArgument(count)
+              .addArgument(blockNumber)
+              .addArgument(peer::getShortNodeId)
+              .log();
           return peer.getHeadersByNumber(blockNumber, count, skip, reverse);
         },
         blockNumber);

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetNodeDataFromPeerTask.java

@@ -66,7 +66,11 @@ public class GetNodeDataFromPeerTask extends AbstractPeerRequestTask<Map<Hash, B
   protected PendingPeerRequest sendRequest() {
     return sendRequestToPeer(
         peer -> {
-          LOG.debug("Requesting {} node data entries from peer {}.", hashes.size(), peer);
+          LOG.atTrace()
+              .setMessage("Requesting {} node data entries from peer {}...")
+              .addArgument(hashes::size)
+              .addArgument(peer::getShortNodeId)
+              .log();
           return peer.getNodeData(hashes);
         },
         pivotBlockNumber);

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetPooledTransactionsFromPeerTask.java

@@ -61,7 +61,11 @@ public class GetPooledTransactionsFromPeerTask extends AbstractPeerRequestTask<L
   protected PendingPeerRequest sendRequest() {
     return sendRequestToPeer(
         peer -> {
-          LOG.debug("Requesting {} transaction pool entries from peer {}.", hashes.size(), peer);
+          LOG.atTrace()
+              .setMessage("Requesting {} transaction pool entries from peer {}...")
+              .addArgument(hashes::size)
+              .addArgument(peer::getShortNodeId)
+              .log();
           return peer.getPooledTransactions(new ArrayList<>(hashes));
         },
         0);

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetReceiptsFromPeerTask.java

@@ -83,7 +83,11 @@ public class GetReceiptsFromPeerTask
             .collect(toList());
     return sendRequestToPeer(
         peer -> {
-          LOG.debug("Requesting {} receipts from peer {}.", blockHeaders.size(), peer);
+          LOG.atTrace()
+              .setMessage("Requesting {} receipts from peer {}...")
+              .addArgument(blockHeaders::size)
+              .addArgument(peer::getShortNodeId)
+              .log();
           return peer.getReceipts(blockHashes);
         },
         maximumRequiredBlockNumber);
@@ -93,7 +97,7 @@ public class GetReceiptsFromPeerTask
   protected Optional<Map<BlockHeader, List<TransactionReceipt>>> processResponse(
       final boolean streamClosed, final MessageData message, final EthPeer peer) {
     if (streamClosed) {
-      // All outstanding requests have been responded to and we still haven't found the response
+      // All outstanding requests have been responded to, and we still haven't found the response
       // we wanted. It must have been empty or contain data that didn't match.
       peer.recordUselessResponse("receipts");
       return Optional.of(emptyMap());

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/ChainHeadTracker.java

@@ -66,7 +66,10 @@ public class ChainHeadTracker implements ConnectCallback {
 
   @Override
   public void onPeerConnected(final EthPeer peer) {
-    LOG.debug("Requesting chain head info from {}", peer);
+    LOG.atDebug()
+        .setMessage("Requesting chain head info from {}...")
+        .addArgument(peer::getShortNodeId)
+        .log();
     GetHeadersFromPeerByHashTask.forSingleHash(
             protocolSchedule,
             ethContext,
@@ -82,14 +85,14 @@ public class ChainHeadTracker implements ConnectCallback {
                 peer.chainState().update(chainHeadHeader);
                 trailingPeerLimiter.enforceTrailingPeerLimit();
                 LOG.atDebug()
-                    .setMessage("Retrieved chain head info {} from {}")
+                    .setMessage("Retrieved chain head info {} from {}...")
                     .addArgument(
                         () ->
                             chainHeadHeader.getNumber()
                                 + " ("
                                 + chainHeadHeader.getBlockHash()
                                 + ")")
-                    .addArgument(peer)
+                    .addArgument(peer::getShortNodeId)
                     .log();
               } else {
                 LOG.debug("Failed to retrieve chain head info. Disconnecting {}", peer, error);

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java

@@ -66,7 +66,7 @@ public class BackwardSyncStep {
     }
 
     final int batchSize = context.getBatchSize();
-    LOG.debug("Requesting headers for hash {}, with batch size {}", hash, batchSize);
+    LOG.trace("Requesting headers for hash {}, with batch size {}", hash, batchSize);
 
     final RetryingGetHeadersEndingAtFromPeerByHashTask
         retryingGetHeadersEndingAtFromPeerByHashTask =

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/range/RangeHeadersFetcher.java

@@ -97,7 +97,7 @@ public class RangeHeadersFetcher {
       final BlockHeader referenceHeader,
       final int headerCount,
       final int skip) {
-    LOG.debug(
+    LOG.trace(
         "Requesting {} range headers, starting from {}, {} blocks apart",
         headerCount,
         referenceHeader.getNumber(),

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

@@ -86,8 +86,8 @@ public class NewPooledTransactionHashesMessageProcessor {
 
       LOG.atTrace()
           .setMessage(
-              "Received pooled transaction hashes message from {}, incoming hashes {}, incoming list {}")
-          .addArgument(peer)
+              "Received pooled transaction hashes message from {}... incoming hashes {}, incoming list {}")
+          .addArgument(() -> peer == null ? null : peer.getShortNodeId())
           .addArgument(incomingTransactionHashes::size)
           .addArgument(incomingTransactionHashes)
           .log();

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

@@ -182,7 +182,7 @@ public class TransactionPool implements BlockAddedObserver {
     final long started = System.currentTimeMillis();
     final int initialCount = transactions.size();
     final List<Transaction> addedTransactions = new ArrayList<>(initialCount);
-    LOG.debug("Adding {} remote transactions", initialCount);
+    LOG.trace("Adding {} remote transactions", initialCount);
 
     final var validationResults =
         sortedBySenderAndNonce(transactions)
@@ -204,7 +204,7 @@ public class TransactionPool implements BlockAddedObserver {
         .addArgument(() -> pendingTransactions.logStats())
         .log();
 
-    LOG.atDebug()
+    LOG.atTrace()
         .setMessage(
             "Added {} transactions to the pool in {}ms, {} not added, current pool stats {}")
         .addArgument(addedTransactions::size)
@@ -350,7 +350,7 @@ public class TransactionPool implements BlockAddedObserver {
                                   .getByBlockHeader(e.getBlock().getHeader())
                                   .getFeeMarket());
                           reAddTransactions(e.getRemovedTransactions());
-                          LOG.atDebug()
+                          LOG.atTrace()
                               .setMessage("Block added event {} processed in {}ms")
                               .addArgument(e)
                               .addArgument(() -> System.currentTimeMillis() - started)

ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/AbstractHandshakeHandler.java

@@ -153,7 +153,7 @@ abstract class AbstractHandshakeHandler extends SimpleChannelInboundHandler<Byte
 
   @Override
   public void exceptionCaught(final ChannelHandlerContext ctx, final Throwable throwable) {
-    LOG.debug("Handshake error:", throwable);
+    LOG.trace("Handshake error:", throwable);
     connectionFuture.completeExceptionally(throwable);
     ctx.close();
   }

ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/HandshakeHandlerOutbound.java

@@ -84,7 +84,7 @@ final class HandshakeHandlerOutbound extends AbstractHandshakeHandler {
         .addListener(
             f -> {
               if (f.isSuccess()) {
-                LOG.debug(
+                LOG.trace(
                     "Wrote initial crypto handshake message to {}.", ctx.channel().remoteAddress());
               }
             });