Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Eth peer logging improvements #6200

Merged
merged 14 commits into from
Nov 28, 2023
Merged

Conversation

macfarla
Copy link
Contributor

  • Moved the full "mismatched network id" message to TRACE and have a brief version at DEBUG
  • moved "Disconnect - Outbound" brief message to INFO
  • moved the EthPeers {} collection logging to TRACE

Copy link

  • I thought about documentation and added the doc-change-required label to this PR if updates are required.
  • I thought about the changelog and included a changelog update if required.
  • If my PR includes database changes (e.g. KeyValueSegmentIdentifier) I have thought about compatibility and performed forwards and backwards compatibility tests

Copy link
Contributor

@fab-10 fab-10 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There is an opportunity for small optimization converting, trace and debug, log statement to their lazy version, since some methods used there have a little overhead.
And would like to have a view of the impact of the info logs on the UX

@@ -257,14 +257,14 @@ public RequestManager.ResponseStream send(
throws PeerNotConnected {
if (connectionToUse.getAgreedCapabilities().stream()
.noneMatch(capability -> capability.getName().equalsIgnoreCase(protocolName))) {
LOG.debug("Protocol {} unavailable for this peer {}", protocolName, this.getShortNodeId());
LOG.debug("Protocol {} unavailable for this peer {}...", protocolName, this.getShortNodeId());
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

small opt

Suggested change
LOG.debug("Protocol {} unavailable for this peer {}...", protocolName, this.getShortNodeId());
LOG.atDebug().setMessage("Protocol {} unavailable for this peer {}...").addArgument(protocolName).addArgument(this::getShortNodeId).log();

ethPeers.peerCount(),
ethPeers);
ethPeers.peerCount());
LOG.trace(ethPeers.toString());
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

small opt

Suggested change
LOG.trace(ethPeers.toString());
LOG.trace(ethPeers);

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I had to do this to get it to compile - is this better?

  LOG.atTrace().addArgument(ethPeers).log();

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok is see the problem with my initial suggestion, it should be LOG.trace("{}", ethPeers);

@@ -394,13 +394,13 @@ public void handleDisconnect(
final DisconnectReason reason,
final boolean initiatedByPeer) {
if (ethPeers.registerDisconnect(connection)) {
LOG.debug(
"Disconnect - {} - {} - {}... - {} peers left\n{}",
LOG.info(
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

how frequent is this one? asking to understand the impact on log UX

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yeah this might be too much for mainnet

2023-11-28 10:52:39.667+10:00 | nioEventLoopGroup-3-8 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0xa7577f327e190458... - 17 peers left
2023-11-28 10:52:50.513+10:00 | nioEventLoopGroup-3-3 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x01 TCP_SUBSYSTEM_ERROR - 0xe108725c42e2aa86... - 16 peers left
2023-11-28 10:52:51.226+10:00 | vert.x-eventloop-thread-0 | WARN  | EngineQosTimer | Execution engine not called in 120 seconds, consensus client may not be connected
2023-11-28 10:52:54.222+10:00 | nioEventLoopGroup-3-10 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0x7a0718e2d7d4dc19... - 16 peers left
2023-11-28 10:52:58.426+10:00 | EthScheduler-Timer-0 | INFO  | PivotSelectorFromSafeBlock | Waiting for consensus client, this may be because your consensus client is still syncing
2023-11-28 10:53:22.017+10:00 | nioEventLoopGroup-3-3 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0x2bf0042844b851bb... - 16 peers left
2023-11-28 10:53:24.321+10:00 | nioEventLoopGroup-3-4 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0x971eaefe449b291f... - 18 peers left
2023-11-28 10:53:24.643+10:00 | nioEventLoopGroup-3-7 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0x73fef41ee12d7fab... - 18 peers left
2023-11-28 10:53:35.287+10:00 | nioEventLoopGroup-3-10 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x01 TCP_SUBSYSTEM_ERROR - 0x442bbbf796325434... - 17 peers left
2023-11-28 10:53:39.201+10:00 | nioEventLoopGroup-3-2 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x01 TCP_SUBSYSTEM_ERROR - 0x47c7f2a91ce28a6a... - 16 peers left
2023-11-28 10:53:54.364+10:00 | nioEventLoopGroup-3-10 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0x971eaefe449b291f... - 17 peers left
2023-11-28 10:53:54.690+10:00 | nioEventLoopGroup-3-6 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0x73fef41ee12d7fab... - 16 peers left
2023-11-28 10:53:58.522+10:00 | EthScheduler-Timer-0 | INFO  | PivotSelectorFromSafeBlock | Waiting for consensus client, this may be because your consensus client is still syncing
2023-11-28 10:54:01.195+10:00 | nioEventLoopGroup-3-1 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0x42f5a99e0c676592... - 16 peers left
2023-11-28 10:54:02.486+10:00 | nioEventLoopGroup-3-1 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0xd2403e175cf04655... - 16 peers left
2023-11-28 10:54:18.531+10:00 | nioEventLoopGroup-3-1 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0x7ad8d195880d5a33... - 16 peers left
2023-11-28 10:54:24.366+10:00 | nioEventLoopGroup-3-5 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0x971eaefe449b291f... - 17 peers left
2023-11-28 10:54:35.919+10:00 | nioEventLoopGroup-3-4 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x01 TCP_SUBSYSTEM_ERROR - 0x6fbc31e076e0ca78... - 16 peers left
2023-11-28 10:54:37.110+10:00 | nioEventLoopGroup-3-8 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0x856d25c9592a8b38... - 16 peers left
2023-11-28 10:54:37.483+10:00 | nioEventLoopGroup-3-6 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0xd8482b28dba149a1... - 16 peers left
2023-11-28 10:54:51.224+10:00 | vert.x-eventloop-thread-0 | WARN  | EngineQosTimer | Execution engine not called in 120 seconds, consensus client may not be connected
2023-11-28 10:54:54.533+10:00 | nioEventLoopGroup-3-5 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0x971eaefe449b291f... - 17 peers left
2023-11-28 10:54:58.600+10:00 | EthScheduler-Timer-0 | INFO  | PivotSelectorFromSafeBlock | Waiting for consensus client, this may be because your consensus client is still syncing
2023-11-28 10:54:58.684+10:00 | nioEventLoopGroup-3-8 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x01 TCP_SUBSYSTEM_ERROR - 0x108097a033125037... - 16 peers left
2023-11-28 10:55:09.313+10:00 | nioEventLoopGroup-3-5 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0x2ad62e0b344afecc... - 16 peers left
2023-11-28 10:55:25.805+10:00 | nioEventLoopGroup-3-7 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0x971eaefe449b291f... - 16 peers left
2023-11-28 10:55:47.271+10:00 | nioEventLoopGroup-3-2 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0x36cee0f8d9c6e883... - 16 peers left
2023-11-28 10:55:55.116+10:00 | nioEventLoopGroup-3-10 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0xaa49d5021cfa3d6a... - 16 peers left
2023-11-28 10:55:58.680+10:00 | EthScheduler-Timer-0 | INFO  | PivotSelectorFromSafeBlock | Waiting for consensus client, this may be because your consensus client is still syncing
2023-11-28 10:56:02.899+10:00 | nioEventLoopGroup-3-8 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0xcee5d198ccbed5b6... - 16 peers left
2023-11-28 10:56:11.524+10:00 | nioEventLoopGroup-3-3 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0xd938bcbb37907241... - 16 peers left
2023-11-28 10:56:24.750+10:00 | nioEventLoopGroup-3-9 | INFO  | EthProtocolManager | Disconnect - Outbound - 0x03 USELESS_PEER - 0x971eaefe449b291f... - 16 peers left
2023-11-28 10:56:51.223+10:00 | vert.x-eventloop-thread-0 | WARN  | EngineQosTimer | Execution engine not called in 120 seconds, consensus client may not be connected

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

changed back to debug

Comment on lines 413 to 415
LOG.debug(
"Mismatched network id: {}, EthPeer {}...", status.networkId(), peer.getShortNodeId());
LOG.trace("Mismatched network id: {}, EthPeer {}", status.networkId(), peer);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
LOG.debug(
"Mismatched network id: {}, EthPeer {}...", status.networkId(), peer.getShortNodeId());
LOG.trace("Mismatched network id: {}, EthPeer {}", status.networkId(), peer);
LOG.atDebug().setMessage(
"Mismatched network id: {}, EthPeer {}...").addArgument(status::networkId).addArgument(peer::getShortNodeId).log();
LOG.atTrace().setMessage("Mismatched network id: {}, EthPeer {}") .addArgument(status::networkId).addArgument(peer).log();

@macfarla
Copy link
Contributor Author

thanks for your review @fab-10 - have made some changes, if you can re-review - thanks!

Copy link
Contributor

@fab-10 fab-10 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

suggested a minor change, then LGTM

Co-authored-by: Fabio Di Fabio <[email protected]>
Signed-off-by: Sally MacFarlane <[email protected]>
@macfarla macfarla enabled auto-merge (squash) November 28, 2023 10:25
@macfarla macfarla merged commit 8f5a444 into hyperledger:main Nov 28, 2023
18 checks passed
@macfarla macfarla deleted the eth-peer-logging branch December 1, 2023 03:50
jflo pushed a commit to jflo/besu that referenced this pull request Dec 4, 2023
* log list of peers at TRACE level

Co-authored-by: Fabio Di Fabio <[email protected]>
Signed-off-by: Sally MacFarlane <[email protected]>

---------

Signed-off-by: Sally MacFarlane <[email protected]>
Co-authored-by: Fabio Di Fabio <[email protected]>
Signed-off-by: Justin Florentine <[email protected]>
jflo pushed a commit to jflo/besu that referenced this pull request Dec 4, 2023
* log list of peers at TRACE level

Co-authored-by: Fabio Di Fabio <[email protected]>
Signed-off-by: Sally MacFarlane <[email protected]>

---------

Signed-off-by: Sally MacFarlane <[email protected]>
Co-authored-by: Fabio Di Fabio <[email protected]>
jflo pushed a commit to jflo/besu that referenced this pull request Dec 4, 2023
* log list of peers at TRACE level

Co-authored-by: Fabio Di Fabio <[email protected]>
Signed-off-by: Sally MacFarlane <[email protected]>

---------

Signed-off-by: Sally MacFarlane <[email protected]>
Co-authored-by: Fabio Di Fabio <[email protected]>
Signed-off-by: Justin Florentine <[email protected]>
gfukushima pushed a commit to gfukushima/besu that referenced this pull request Dec 15, 2023
* log list of peers at TRACE level

Co-authored-by: Fabio Di Fabio <[email protected]>
Signed-off-by: Sally MacFarlane <[email protected]>

---------

Signed-off-by: Sally MacFarlane <[email protected]>
Co-authored-by: Fabio Di Fabio <[email protected]>
Signed-off-by: Gabriel Fukushima <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants