Network logging bugfixes and improvements

[halfalicious]

Various network logging bugfixes and changes. Bugfixes:

• Move "unsolicited neighbours packet" message from "net" to "discov" log channel since that's the channel that the rest of the discovery messages are logged to
• Fix log message that we write when we send a p2p capability pong (we incorrectly say we're sending a ping)

Other logging changes:

• Log messages related to p2p capability messaging to a new "p2pcap" log channel
• Log incoming capability packet type string
• Add node id and endpoint information to some network log messages
• Remove redundant "Packet" from p2p capability packet type strings
• Remove logging of RLP payloads in Session (this adds clutter to the log output and makes it harder to visually parse - I think it's safe to remove this information since I can't see us ever using it for debugging, if it turns out we need it we can always add it back)

[codecov-io]

Codecov Report

Merging #5591 into master will decrease coverage by 0.03%.
The diff coverage is 53.76%.

@@            Coverage Diff             @@
##           master    #5591      +/-   ##
==========================================
- Coverage   62.25%   62.21%   -0.04%     
==========================================
  Files         347      347              
  Lines       29229    29280      +51     
  Branches     3306     3309       +3     
==========================================
+ Hits        18197    18218      +21     
- Misses       9844     9873      +29     
- Partials     1188     1189       +1

[halfalicious]

Rebased + added changelog update

[halfalicious]

Squashed some commits

[gumb0]

Don't forget to add p2pcap to the list of channels in aleth/main.cpp

[gumb0]

I'm not sure about logging everywhere in Session class << m_info.id << "@" << m_socket->remoteEndpoint();

Here LOG_SCOPED_CONTEXT is supposed to add a prefix of id+clientVersion for each log message inside network handlers. Isn't at least m_info.id duplicated in logs this way?

I suspect that sometimes IDs could be different, like when BlockChainSync code is called inside the handler of the message from one peer, and this code sends a message to another peer.
In this case, maybe it's better to remove LOG_SCOPED_CONTEXT stuff now? Though then clientVersion of the peers won't as visible in logs as now, it seems useful, too... What do you think?

[halfalicious]

@gumb0 : I like having the client information in the log messages, though I don't have a concrete example of when it has helped me debug something yet. I think that prefixing each log message with the node id + client information makes the log messages a little counter-intuitive, for example, the following message could be logged when we receive a Pong p2p capability message from a node but the message reads as if 865a6325 received the pong:

p2p p2pcap 865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 Receiving Pong

An option is to remove the LOG_SCOPED_CONTEXT and to instead log the client information at the end of each message e.g.

TRACE 05-07 21:03:32 p2p p2pcap Pong to ##865a6325…@52.176.100.77:30303 (Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1)

I think this is more readable, though it makes the log statements themselves more cumbersome (as you called out in my RLPXHandshake logging changes). Perhaps we could also create a logging wrapper function such as:

inline void logMessage(char const* _message, char const* _channel, Verbosity _verbosity)
{
      clog(_verbosity, _channel) << _message << " (" << m_info.clientVersion << "|" << m_info.id << "|" << m_socket->remoteEndpoint() << ")";
}

Thoughts?

[gumb0]

I think I dislike repeating clientVersion many times, it bloats the log. If we output it once, say for Hello message, it should be easy enough to find it in the log for particular NodeID, when we need it.

[gumb0]

Another thing: if we repeat this << m_info.id << "@" << m_socket->remoteEndpoint(); in every message and these values are constant, can we create a logger for this, that adds them as a Context attribute, similar to what you did in RLPXHandshake ?

This and removing LOG_SCOPED_CONTEXT can be done as a separate PR.

[gumb0]

The downside to removing LOG_SCOPED_CONTEXT would be that we won't see this context for the messages coming from BlockChainSync, not sure how useful it is. Maybe it's fine to remove, as all network handling happens sequentially in one thread and we should be able to find this context earlier in the log.

[halfalicious]

I think I dislike repeating clientVersion many times, it bloats the log. If we output it once, say for Hello message, it should be easy enough to find it in the log for particular NodeID, when we need it.

Yes, but the Hello might be long in the past so it might not be accessible in the console log output anymore. This might be okay though since we also periodically log connected peers, though only at trace level:

aleth/libp2p/Host.cpp

Line 868 in 7ecf42b

LOG(m_detailsLogger) << "Peers: " << peerSessionInfos();

Host::m_detailLogger is defined here:

aleth/libp2p/Host.h

Line 382 in 7ecf42b

Logger m_detailsLogger{createLogger(VerbosityTrace, "net")};

Maybe we should change the verbosity level of this log message to debug level so that it's more readily available for debugging purposes?

[halfalicious]

e repeat this << m_info.id << "@" << m_socket->remoteEndpoint(); in every message and these values are constant, can we create a logger for this, that adds them as a Context attribute...

@gumb0 Is there a way to add the context to the end of a log message? I think including remote endpoint information at the beginning of a log message makes the log a little counter-intuitive.

[gumb0]

Is there a way to add the context to the end of a log message?

Not right now, but I think it's simple enough to add this. We could rename Context attribute to Prefix, then add another Suffix one, and your logger would fill the Suffix

The changes will be need only here

aleth/libdevcore/Log.cpp

Line 51 in 4e63cf2

BOOST_LOG_ATTRIBUTE_KEYWORD(context, "Context", std::string)

and when we output it in formatter here

aleth/libdevcore/Log.cpp

Lines 99 to 100 in 4e63cf2

	if (boost::log::expressions::has_attr(context)(_rec))
	_strm << EthNavy << _rec[context] << EthReset " ";

[gumb0]

Even if it's difficult to create a logger in Session with Context that automatically adds NodeID and IP to the messages, I think it's still better to create a member variable logger(s) instead of using clog(VerbosityTrace, "p2pcap")
But this can be done in another PR.

[halfalicious]

logger in Session with Context that automatically adds NodeID and IP to the messages, I think it's still better to create a member variable logger(s) instead of using clog(VerbosityTrace, "p2pcap")

@gumb0 : Agreed. For reference, clog(VerbosityTrace, "p2pcap") and LOG(m_logger) where m_logger is defined as Logger m_logger{createLogger(VerbosityTrace, "p2pcap")} are functionally equivalent?

[gumb0]

@halfalicious Not exactly, clog(...) macro uses a global thread-safe logger, while createLogger() creates a non-thread-safe logger, so it doesn't have the overhead of thread-safety, and so should be more efficient.

Actually now I think that the reason global loggers like cnetdetails were used in Session class originally could be that some methods are called from different threads... Not sure if it's correct assumption, so if you change it to member variable logger, take care to use it only in network thread