From fd187bcd91630fe5cca6eb8737980d480098bf1a Mon Sep 17 00:00:00 2001 From: Sally MacFarlane Date: Thu, 30 Nov 2023 19:51:01 +1000 Subject: [PATCH] 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 Signed-off-by: Sally MacFarlane --------- Signed-off-by: Sally MacFarlane Signed-off-by: Fabio Di Fabio Co-authored-by: Fabio Di Fabio --- .../api/query/cache/TransactionLogBloomCacher.java | 5 ++++- .../besu/ethereum/eth/manager/EthPeer.java | 14 +++++++++----- .../task/AbstractGetHeadersFromPeerTask.java | 6 +++--- .../task/AbstractRetryingSwitchingPeerTask.java | 2 +- ...fferedGetPooledTransactionsFromPeerFetcher.java | 8 ++++---- .../eth/manager/task/GetBodiesFromPeerTask.java | 8 ++++++-- .../manager/task/GetHeadersFromPeerByHashTask.java | 4 ++-- .../task/GetHeadersFromPeerByNumberTask.java | 11 ++++++----- .../eth/manager/task/GetNodeDataFromPeerTask.java | 6 +++++- .../task/GetPooledTransactionsFromPeerTask.java | 6 +++++- .../eth/manager/task/GetReceiptsFromPeerTask.java | 8 ++++++-- .../besu/ethereum/eth/sync/ChainHeadTracker.java | 9 ++++++--- .../eth/sync/backwardsync/BackwardSyncStep.java | 2 +- .../eth/sync/range/RangeHeadersFetcher.java | 2 +- ...NewPooledTransactionHashesMessageProcessor.java | 4 ++-- .../ethereum/eth/transactions/TransactionPool.java | 6 +++--- .../netty/AbstractHandshakeHandler.java | 2 +- .../netty/HandshakeHandlerOutbound.java | 2 +- 18 files changed, 66 insertions(+), 39 deletions(-) diff --git a/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/query/cache/TransactionLogBloomCacher.java b/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/query/cache/TransactionLogBloomCacher.java index dd6fed957ab..31132a4655e 100644 --- a/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/query/cache/TransactionLogBloomCacher.java +++ b/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/query/cache/TransactionLogBloomCacher.java @@ -159,7 +159,10 @@ void cacheLogsBloomForBlockHeader( 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 { diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthPeer.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthPeer.java index 65f9cea8dbe..4e734447035 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthPeer.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthPeer.java @@ -210,16 +210,20 @@ public void removeChainEstimatedHeightListener(final long listenerId) { } 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); } diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractGetHeadersFromPeerTask.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractGetHeadersFromPeerTask.java index 9ec56d4c828..83af1e0b32d 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractGetHeadersFromPeerTask.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractGetHeadersFromPeerTask.java @@ -125,11 +125,11 @@ protected Optional> processResponse( 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); } diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractRetryingSwitchingPeerTask.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractRetryingSwitchingPeerTask.java index 24ee859baf9..f9400a6dac6 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractRetryingSwitchingPeerTask.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/AbstractRetryingSwitchingPeerTask.java @@ -145,7 +145,7 @@ private void refreshPeers() { 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) diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/BufferedGetPooledTransactionsFromPeerFetcher.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/BufferedGetPooledTransactionsFromPeerFetcher.java index 215202f8341..0e414ba5db8 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/BufferedGetPooledTransactionsFromPeerFetcher.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/BufferedGetPooledTransactionsFromPeerFetcher.java @@ -89,10 +89,10 @@ public void requestTransactions() { 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 @@ private List getTxHashesAnnounced() { 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(); diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetBodiesFromPeerTask.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetBodiesFromPeerTask.java index 9e1df148c12..4cd66830251 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetBodiesFromPeerTask.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetBodiesFromPeerTask.java @@ -93,7 +93,11 @@ protected PendingPeerRequest sendRequest() { 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 @@ protected PendingPeerRequest sendRequest() { protected Optional> 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()); diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetHeadersFromPeerByHashTask.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetHeadersFromPeerByHashTask.java index f3e931b4bae..4fb2ef226f4 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetHeadersFromPeerByHashTask.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetHeadersFromPeerByHashTask.java @@ -119,11 +119,11 @@ public static AbstractGetHeadersFromPeerTask forSingleHash( 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); }, diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetHeadersFromPeerByNumberTask.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetHeadersFromPeerByNumberTask.java index f136fc57eb7..3f6e153df37 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetHeadersFromPeerByNumberTask.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetHeadersFromPeerByNumberTask.java @@ -77,11 +77,12 @@ public static AbstractGetHeadersFromPeerTask forSingleNumber( 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); diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetNodeDataFromPeerTask.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetNodeDataFromPeerTask.java index c5d01632281..d6b0de35069 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetNodeDataFromPeerTask.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetNodeDataFromPeerTask.java @@ -66,7 +66,11 @@ public static GetNodeDataFromPeerTask forHashes( 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); diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetPooledTransactionsFromPeerTask.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetPooledTransactionsFromPeerTask.java index 06151ba68c8..e3a45418d18 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetPooledTransactionsFromPeerTask.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetPooledTransactionsFromPeerTask.java @@ -61,7 +61,11 @@ public Set getTransactionHashes() { 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); diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetReceiptsFromPeerTask.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetReceiptsFromPeerTask.java index dace85a202b..42e0928829f 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetReceiptsFromPeerTask.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/task/GetReceiptsFromPeerTask.java @@ -83,7 +83,11 @@ protected PendingPeerRequest sendRequest() { .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 @@ protected PendingPeerRequest sendRequest() { protected Optional>> 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()); diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/ChainHeadTracker.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/ChainHeadTracker.java index d871b07a6e0..5e4862da1ec 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/ChainHeadTracker.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/ChainHeadTracker.java @@ -66,7 +66,10 @@ public static void trackChainHeadForPeers( @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 void onPeerConnected(final EthPeer peer) { 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); diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java index 10315a60102..6f9a5822de1 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncStep.java @@ -66,7 +66,7 @@ protected CompletableFuture> requestHeaders(final Hash hash) { } 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 = diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/range/RangeHeadersFetcher.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/range/RangeHeadersFetcher.java index 68e7d193b99..8ee1dc28a43 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/range/RangeHeadersFetcher.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/sync/range/RangeHeadersFetcher.java @@ -97,7 +97,7 @@ private CompletableFuture> requestHeaders( final BlockHeader referenceHeader, final int headerCount, final int skip) { - LOG.debug( + LOG.trace( "Requesting {} range headers, starting from {}, {} blocks apart", headerCount, referenceHeader.getNumber(), diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/transactions/NewPooledTransactionHashesMessageProcessor.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/transactions/NewPooledTransactionHashesMessageProcessor.java index ede1b60beb1..f447c1df315 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/transactions/NewPooledTransactionHashesMessageProcessor.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/transactions/NewPooledTransactionHashesMessageProcessor.java @@ -86,8 +86,8 @@ private void processNewPooledTransactionHashesMessage( 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(); diff --git a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/transactions/TransactionPool.java b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/transactions/TransactionPool.java index bb0cdf70eb6..edefbc17a36 100644 --- a/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/transactions/TransactionPool.java +++ b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/transactions/TransactionPool.java @@ -182,7 +182,7 @@ public Map> addRemoteTransactio final long started = System.currentTimeMillis(); final int initialCount = transactions.size(); final List 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 Map> addRemoteTransactio .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 void onBlockAdded(final BlockAddedEvent event) { .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) diff --git a/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/AbstractHandshakeHandler.java b/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/AbstractHandshakeHandler.java index 3a827403ec3..003a6ab1d9d 100644 --- a/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/AbstractHandshakeHandler.java +++ b/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/AbstractHandshakeHandler.java @@ -153,7 +153,7 @@ private void disconnect( @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(); } diff --git a/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/HandshakeHandlerOutbound.java b/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/HandshakeHandlerOutbound.java index 1c1391f2f79..205b6f655cc 100644 --- a/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/HandshakeHandlerOutbound.java +++ b/ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/HandshakeHandlerOutbound.java @@ -84,7 +84,7 @@ public void channelActive(final ChannelHandlerContext ctx) throws Exception { .addListener( f -> { if (f.isSuccess()) { - LOG.debug( + LOG.trace( "Wrote initial crypto handshake message to {}.", ctx.channel().remoteAddress()); } });