Skip to content
This repository was archived by the owner on Oct 28, 2021. It is now read-only.

Clean up RLPX handshake logging#5568

Merged
halfalicious merged 11 commits intomasterfrom
p2p-logging
Apr 16, 2019
Merged

Clean up RLPX handshake logging#5568
halfalicious merged 11 commits intomasterfrom
p2p-logging

Conversation

@halfalicious
Copy link
Contributor

@halfalicious halfalicious commented Apr 13, 2019

Clean up the RLPX handshake logging. I've done the following:

  • Move the RLPX handshake logs to a new log channel. They were being logged to the "net" log channel - a lot of p2p logs were written to this channel which made it difficult to wade through the output when debugging (and we couldn't filter logs to just rlpx handshake-specific output). I've created a new "rlpx" channel with 2 verbosities - "error" for internal errors and "debug" for everything else. I considered logging "handshake failed" messages with "warning" verbosity but handshakes fail pretty often for valid reasons and warning logs are displayed with the default Aleth verbosity level (2) so this would result in a lot of log spew that users don't care about in most cases.
  • Add remote endpoint information to each log message so that it's easier to track which connection log messages map to.
  • Miscellaneous cleanup (e.g. add helper function for determining if current connection is inbound vs outbound, add helper function for mapping a PacketType to string so packet type values can be included in packet type mismatch error messages, only log boost error code in "Handshake Failed" error message if the error code indicates an error, change some literals to constexpr if they're used more than once)

There are still opportunities to clean up the output even more - for example, I think the "Handshake Disconnect" messages can be too verbose (in some cases there are something like 3 messages are logged on a disconnect). However, these changes improve things significantly and further output cleanup isn't critical so I think it can be taken care of in a future PR.

Here's a log output snippet before the changes:

TRACE 04-13 15:33:02 p2p  net    Attempting connection to node ##30b7ab30…@52.176.7.10:30303 from ##02cb92f8…
TRACE 04-13 15:33:02 p2p  net    Attempting connection to node ##94c15d1b…@192.81.208.223:30303 from ##02cb92f8…
TRACE 04-13 15:33:02 p2p  net    Attempting connection to node ##6332792c…@52.232.243.152:30303 from ##02cb92f8…
TRACE 04-13 15:33:02 p2p  net    Connecting to ##aa36fdf3…@13.93.211.84:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress sending auth to 13.93.211.84:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress receiving ack from 13.93.211.84:30303
TRACE 04-13 15:33:02 p2p  net    Connecting to ##3f1d1204…@13.93.211.84:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress sending auth to 13.93.211.84:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress receiving ack from 13.93.211.84:30303
TRACE 04-13 15:33:02 p2p  net    Connecting to ##30b7ab30…@52.176.7.10:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress sending auth to 52.176.7.10:30303
TRACE 04-13 15:33:02 p2p  net    Connecting to ##865a6325…@52.176.100.77:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress sending auth to 52.176.100.77:30303
TRACE 04-13 15:33:02 p2p  net    Connecting to ##15ac307a…@52.176.7.10:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress sending auth to 52.176.7.10:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress receiving ack from 52.176.7.10:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress receiving ack from 52.176.100.77:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress receiving ack from 52.176.7.10:30303
TRACE 04-13 15:33:02 p2p  net    Connecting to ##6332792c…@52.232.243.152:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress sending auth to 52.232.243.152:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress receiving ack from 52.232.243.152:30303
DEBUG 04-13 15:33:02 p2p  net    p2p.host.nodeTable.events.nodeEntryAdded ##a979fb57…
DEBUG 04-13 15:33:02 p2p  net    p2p.host.nodeTable.events.nodeEntryAdded ##158f8aab…
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress sending capabilities handshake
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress recvd hello header
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress hello frame: invalid packet type
TRACE 04-13 15:33:02 p2p  net    Handshake Failed (I/O Error: The operation completed successfully)
TRACE 04-13 15:33:02 p2p  net    Disconnecting 52.176.7.10:30303 (Handshake Failed)
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress sending capabilities handshake
TRACE 04-13 15:33:02 p2p  net    Connecting to ##a979fb57…@52.16.188.185:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress sending auth to 52.16.188.185:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress receiving ack from 52.16.188.185:30303
TRACE 04-13 15:33:02 p2p  net    Connecting to ##158f8aab…@13.75.154.138:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress sending auth to 13.75.154.138:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress receiving ack from 13.75.154.138:30303
TRACE 04-13 15:33:02 p2p  net    Connecting to ##78de8a09…@191.235.84.50:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress sending auth to 191.235.84.50:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress receiving ack from 191.235.84.50:30303
DEBUG 04-13 15:33:02 p2p  net    p2p.host.nodeTable.events.nodeEntryAdded ##78de8a09…
TRACE 04-13 15:33:02 p2p  net    Attempting connection to node ##78de8a09…@191.235.84.50:30303 from ##02cb92f8…
DEBUG 04-13 15:33:02 p2p  net    p2p.host.nodeTable.events.nodeEntryAdded ##669f45b6…
DEBUG 04-13 15:33:02 p2p  net    p2p.host.peers.events.peerAdded ##669f45b6… 52.74.57.123:30303
TRACE 04-13 15:33:02 p2p  net    Attempting connection to node ##669f45b6…@52.74.57.123:30303 from ##02cb92f8…
TRACE 04-13 15:33:02 p2p  net    Connecting to ##1118980b…@52.74.57.123:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress sending auth to 52.74.57.123:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress receiving ack from 52.74.57.123:30303
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress recvd hello header
TRACE 04-13 15:33:02 p2p  net    p2p.connect.egress hello frame: success. starting session.
DEBUG 04-13 15:33:02 p2p  net    Hello: Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 V[5] ##865a6325… (eth,63) 30303
DEBUG 04-13 15:33:02 p2p  net    New session for capability eth; idOffset: 16
TRACE 04-13 15:33:02 p2p  net    <- [ 0x3F, 0x3, 0x28C23CA5E068A, 0x2A3B3B30554F25298E884C1C675BB131A95278C4447301CD55775BC8A2AA030F, 0x41941023680923E0FE4D74A34BD

And here's the log output now:

TRACE 04-14 14:55:57 p2p  net    Attempting connection to node ##6332792c…@52.232.243.152:30303 from ##9fd99964…
TRACE 04-14 14:55:57 p2p  net    Connecting to ##aa36fdf3…@13.93.211.84:30303
DEBUG 04-14 14:55:57 p2p  rlpx   p2p.connect.egress: auth to ##aa36fdf3…@13.93.211.84:30303
TRACE 04-14 14:55:57 p2p  net    Connecting to ##3f1d1204…@13.93.211.84:30303
DEBUG 04-14 14:55:57 p2p  rlpx   p2p.connect.egress: auth to ##3f1d1204…@13.93.211.84:30303
DEBUG 04-14 14:55:57 p2p  rlpx   p2p.connect.egress: ack from ##aa36fdf3…@13.93.211.84:30303
DEBUG 04-14 14:55:57 p2p  rlpx   p2p.connect.egress: ack from ##3f1d1204…@13.93.211.84:30303
TRACE 04-14 14:55:57 p2p  net    Connecting to ##865a6325…@52.176.100.77:30303
DEBUG 04-14 14:55:57 p2p  rlpx   p2p.connect.egress: auth to ##865a6325…@52.176.100.77:30303
DEBUG 04-14 14:55:57 p2p  rlpx   p2p.connect.egress: ack from ##865a6325…@52.176.100.77:30303
TRACE 04-14 14:55:57 p2p  net    Connecting to ##30b7ab30…@52.176.7.10:30303
DEBUG 04-14 14:55:57 p2p  rlpx   p2p.connect.egress: auth to ##30b7ab30…@52.176.7.10:30303
DEBUG 04-14 14:55:57 p2p  rlpx   p2p.connect.egress: ack from ##30b7ab30…@52.176.7.10:30303
TRACE 04-14 14:55:57 p2p  net    Connecting to ##6332792c…@52.232.243.152:30303
DEBUG 04-14 14:55:57 p2p  rlpx   p2p.connect.egress: auth to ##6332792c…@52.232.243.152:30303
DEBUG 04-14 14:55:57 p2p  rlpx   p2p.connect.egress: ack from ##6332792c…@52.232.243.152:30303
DEBUG 04-14 14:55:57 p2p  net    p2p.host.nodeTable.events.nodeEntryAdded ##15ac307a…
DEBUG 04-14 14:55:57 p2p  net    p2p.host.peers.events.peerAdded ##15ac307a… 52.176.7.10:30303
TRACE 04-14 14:55:57 p2p  net    Attempting connection to node ##15ac307a…@52.176.7.10:30303 from ##9fd99964…
DEBUG 04-14 14:55:57 p2p  net    p2p.host.nodeTable.events.nodeEntryAdded ##a979fb57…
DEBUG 04-14 14:55:57 p2p  net    p2p.host.nodeTable.events.nodeEntryAdded ##158f8aab…
TRACE 04-14 14:55:58 p2p  net    Connecting to ##a979fb57…@52.16.188.185:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: auth to ##a979fb57…@52.16.188.185:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: ack from ##a979fb57…@52.16.188.185:30303
TRACE 04-14 14:55:58 p2p  net    Connecting to ##15ac307a…@52.176.7.10:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: auth to ##15ac307a…@52.176.7.10:30303
TRACE 04-14 14:55:58 p2p  net    Connecting to ##158f8aab…@13.75.154.138:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: auth to ##158f8aab…@13.75.154.138:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: ack from ##15ac307a…@52.176.7.10:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: ack from ##158f8aab…@13.75.154.138:30303
TRACE 04-14 14:55:58 p2p  net    Connecting to ##78de8a09…@191.235.84.50:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: auth to ##78de8a09…@191.235.84.50:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: ack from ##78de8a09…@191.235.84.50:30303
TRACE 04-14 14:55:58 p2p  net    Connecting to ##1118980b…@52.74.57.123:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: auth to ##1118980b…@52.74.57.123:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: ack from ##1118980b…@52.74.57.123:30303
DEBUG 04-14 14:55:58 p2p  net    p2p.host.nodeTable.events.nodeEntryAdded ##78de8a09…
TRACE 04-14 14:55:58 p2p  net    Attempting connection to node ##78de8a09…@191.235.84.50:30303 from ##9fd99964…
DEBUG 04-14 14:55:58 p2p  net    p2p.host.nodeTable.events.nodeEntryAdded ##669f45b6…
DEBUG 04-14 14:55:58 p2p  net    p2p.host.peers.events.peerAdded ##669f45b6… 52.74.57.123:30303
TRACE 04-14 14:55:58 p2p  net    Attempting connection to node ##669f45b6…@52.74.57.123:30303 from ##9fd99964…
DEBUG 04-14 14:55:58 p2p  net    p2p.host.nodeTable.events.nodeEntryAdded ##865a6325…
TRACE 04-14 14:55:58 p2p  net    Attempting connection to node ##865a6325…@52.176.100.77:30303 from ##9fd99964…
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: HelloPacket to ##15ac307a…@52.176.7.10:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: Frame header from ##15ac307a…@52.176.7.10:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: Successfully decrypted frame header from ##15ac307a…@52.176.7.10:30303. Validating contents...
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: Frame body from ##15ac307a…@52.176.7.10:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: Invalid packet type. Expected: HelloPacket, received: DisconnectPacket (##15ac307a…@52.176.7.10:30303)
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: Handshake Failed (##15ac307a…@52.176.7.10:30303)
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: Disconnecting ##15ac307a…@52.176.7.10:30303 (Handshake Failed)
TRACE 04-14 14:55:58 p2p  net    Connecting to ##865a6325…@52.176.100.77:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: auth to ##865a6325…@52.176.100.77:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: ack from ##865a6325…@52.176.100.77:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: HelloPacket to ##a979fb57…@52.16.188.185:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: Frame header from ##a979fb57…@52.16.188.185:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: Successfully decrypted frame header from ##a979fb57…@52.16.188.185:30303. Validating contents...
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: Frame body from ##a979fb57…@52.16.188.185:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: Invalid packet type. Expected: HelloPacket, received: DisconnectPacket (##a979fb57…@52.16.188.185:30303)
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: Handshake Failed (##a979fb57…@52.16.188.185:30303)
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: Disconnecting ##a979fb57…@52.16.188.185:30303 (Handshake Failed)
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: HelloPacket to ##158f8aab…@13.75.154.138:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: Frame header from ##158f8aab…@13.75.154.138:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: Successfully decrypted frame header from ##158f8aab…@13.75.154.138:30303. Validating contents...
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: Frame body from ##158f8aab…@13.75.154.138:30303
DEBUG 04-14 14:55:58 p2p  rlpx   p2p.connect.egress: Invalid packet type. Expected: HelloPacket, received: DisconnectPacket (##158f8aab…@13.75.154.138:30303)

Also ensure that RLPX log messages have remote pubkey and endpoint information
Change RLPXHandshake timer from boost deadline timer to boost steady timer so we can use std::chrono. Also use constexpr where possible.
Add an error logger and use it when error conditions occur (e.g. received invalid packet type) and convert all cnet* log calls to use RLPXHandshake loggers. Remove "received" / "sending" from log messages.
Also only log boost error code in "handshake failed" message if handshake failed because of a boost error.
Add connection direction information to some error messages and overload the << operator for std::ostream so that abridged NodeIDs are written.
@halfalicious halfalicious requested review from chfast and gumb0 and removed request for gumb0 April 13, 2019 22:35
@halfalicious halfalicious changed the title Clean up RLPX handshake logging [WIP] Clean up RLPX handshake logging Apr 13, 2019
@codecov-io
Copy link

codecov-io commented Apr 13, 2019

Codecov Report

Merging #5568 into master will decrease coverage by 0.03%.
The diff coverage is 46.82%.

Impacted file tree graph

@@            Coverage Diff            @@
##           master   #5568      +/-   ##
=========================================
- Coverage   62.13%   62.1%   -0.04%     
=========================================
  Files         347     347              
  Lines       28982   29041      +59     
  Branches     3284    3287       +3     
=========================================
+ Hits        18009   18036      +27     
- Misses       9796    9832      +36     
+ Partials     1177    1173       -4

@halfalicious halfalicious changed the title [WIP] Clean up RLPX handshake logging Clean up RLPX handshake logging Apr 13, 2019
@halfalicious
Copy link
Contributor Author

Squashed some commits

@halfalicious
Copy link
Contributor Author

I'm occasionally seeing some messages being logged twice:

DEBUG 04-14 21:58:07 p2p  rlpx   p2p.connect.egress: HelloPacket to ##a979fb57…@52.16.188.185:30303
DEBUG 04-14 21:58:07 p2p  rlpx   p2p.connect.egress: HelloPacket to ##865a6325…@52.176.100.77:30303
DEBUG 04-14 21:58:07 p2p  rlpx   p2p.connect.egress: HelloPacket to ##865a6325…@52.176.100.77:30303
DEBUG 04-14 21:58:07 p2p  rlpx   p2p.connect.egress: Frame header from ##a979fb57…@52.16.188.185:30303
DEBUG 04-14 21:58:07 p2p  rlpx   p2p.connect.egress: HelloPacket to ##158f8aab…@13.75.154.138:30303
DEBUG 04-14 21:58:07 p2p  rlpx   p2p.connect.egress: Frame header from ##865a6325…@52.176.100.77:30303
DEBUG 04-14 21:58:07 p2p  rlpx   p2p.connect.egress: Frame header from ##865a6325…@52.176.100.77:30303

I don't think this is due to my changes since I didn't modify any logic. I'll file a new issue once this PR has been merged.

Copy link
Member

@gumb0 gumb0 left a comment

Choose a reason for hiding this comment

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

  1. That's a lot of messages, I'm for leaving it all at Trace level.

  2. An idea to make logging code less verbose: you could make a logger that adds connectionDirectionString() to each message.
    Something like this in RLPXHandshake constructor should be enough:

m_logger.add_attribute("Context", boost::log::attrs::constant<std::string>(connectionDirectionString()));

https://www.boost.org/doc/libs/1_56_0/libs/log/doc/html/log/detailed/attributes.html#log.detailed.attributes.constant

Log formatter will output this Context attribute if it's not empty as a prefix to each message (it's currently used in capability/sync messages)

Also maybe m_remote and m_socket->remoteEndpoint(); belong to this context, too.

Change position of const keyword, make some variables const, remove unnecessary "p2p.connect", change log level to trace
@halfalicious
Copy link
Contributor Author

halfalicious commented Apr 16, 2019

matter will output this Context attribute if it's not empty as a prefix to each message (it's currently used in capability/sync messages)

Thanks for bringing this up 😄 Where is it used in capability / sync messages? I did a search for add_attribute but didn't find anything?

I've added an attribute for the connection direction string but the string is only being included in some log messages:

TRACE 04-15 21:05:27 p2p  rlpx   ack from ##6332792c…@52.232.243.152:30303
TRACE 04-15 21:05:27 p2p  rlpx   HelloPacket to ##15ac307a…@52.176.7.10:30303
TRACE 04-15 21:05:27 p2p  rlpx   Frame header from ##15ac307a…@52.176.7.10:30303
TRACE 04-15 21:05:27 p2p  rlpx   egress: Successfully decrypted frame header from ##15ac307a…@52.176.7.10:30303. Validating contents...
TRACE 04-15 21:05:27 p2p  rlpx   Frame body from ##15ac307a…@52.176.7.10:30303
TRACE 04-15 21:05:27 p2p  rlpx   egress: Invalid packet type. Expected: HelloPacket, received: DisconnectPacket (##15ac307a…@52.176.7.10:30303)

Rather than spend more time on this, I'd like to take care of this in a future PR. I also want to add attributes for the remote node ID (pubkey) and endpoint (when the socket is connected) but I think that's a little more complicated because I'd need to do some custom formatting to keep the messages readable. Also, the remote endpoint wouldn't be a constant so I'd have to probably define a new attribute type.

I'll file a new issue to track this work once this PR has been merged.

@gumb0
Copy link
Member

gumb0 commented Apr 16, 2019

Where is it used in capability / sync messages? I did a search for add_attribute but didn't find anything?

It's used in a different way - with LOG_SCOPED_CONTEXT in Session implementation (it adds an attribute for all messages inside the scope, then deletes it at scope exit)

I also want to add attributes for the remote node ID (pubkey) and endpoint (when the socket is connected) but I think that's a little more complicated because I'd need to do some custom formatting to keep the messages readable.

Adding new log attributes probably is not a good idea, because current formatter (defined in Log.cpp) will not output them, and we wouldn't want to handle p2p-specific stuff in Log.cpp I think. I would put all of it into Context (like all messages starting with prefix like egress ##6332792c…@52.232.243.152:30303 )

Also, the remote endpoint wouldn't be a constant so I'd have to probably define a new attribute type.

It's also possible to set Context to result of a function call, not constant.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants