Network logging bugfixes and improvements

CHANGELOG.md

@@ -8,6 +8,7 @@
 - Added: [#5564](https://github.com/ethereum/aleth/pull/5564) Improved help output of Aleth by adding list of channels.
 - Added: [#5575](https://github.com/ethereum/aleth/pull/5575) Log active peer count and peer list every 30 seconds.
 - Added: [#5580](https://github.com/ethereum/aleth/pull/5580) Enable syncing from ETC nodes for blocks < dao hard fork block.
+- Added: [#5591](https://github.com/ethereum/aleth/pull/5591) Network logging bugfixes and improvements.
 - Changed: [#5559](https://github.com/ethereum/aleth/pull/5559) Update peer validation error messages.
 - Changed: [#5568](https://github.com/ethereum/aleth/pull/5568) Improve rlpx handshake log messages and create new rlpx log channel.
 - Changed: [#5576](https://github.com/ethereum/aleth/pull/5576) Moved sstore_combinations and static_Call50000_sha256 tests to stTimeConsuming test suite. (testeth runs them only with `--all` flag)

libethereum/CommonNet.cpp

@@ -24,5 +24,48 @@ using namespace std;
 using namespace dev;
 using namespace dev::eth;
 
+namespace dev
+{
+namespace eth
+{
 #pragma GCC diagnostic ignored "-Wunused-variable"
-namespace { char dummy; }
+namespace
+{
+char dummy;
+}
+
+
+char const* ethPacketTypeToString(EthSubprotocolPacketType _packetType)
+{
+    switch (_packetType)
+    {
+    case StatusPacket:
+        return "Status";
+    case NewBlockHashesPacket:
+        return "NewBlockHashes";
+    case TransactionsPacket:
+        return "Transactions";
+    case GetBlockHeadersPacket:
+        return "GetBlockHeaders";
+    case BlockHeadersPacket:
+        return "BlockHeaders";
+    case GetBlockBodiesPacket:
+        return "GetBlockBodies";
+    case BlockBodiesPacket:
+        return "BlockBodies";
+    case NewBlockPacket:
+        return "NewBlock";
+    case GetNodeDataPacket:
+        return "GetNodeData";
+    case NodeDataPacket:
+        return "NodeData";
+    case GetReceiptsPacket:
+        return "GetReceipts";
+    case ReceiptsPacket:
+        return "Receipts";
+    default:
+        return "UnknownEthPacket";
+    }
+}
+}  // namespace eth
+}  // namespace dev

libethereum/CommonNet.h

@@ -50,7 +50,7 @@ class TransactionQueue;
 class EthereumCapability;
 class EthereumPeer;
 
-enum SubprotocolPacketType: byte
+enum EthSubprotocolPacketType : byte
 {
     StatusPacket = 0x00,
     NewBlockHashesPacket = 0x01,
@@ -69,6 +69,8 @@ enum SubprotocolPacketType: byte
     PacketCount
 };
 
+char const* ethPacketTypeToString(EthSubprotocolPacketType _packetType);
+
 enum class Asking
 {
     State,

libethereum/EthereumCapability.h

@@ -92,6 +92,10 @@ class EthereumCapability : public p2p::CapabilityFace
     unsigned version() const override { return c_protocolVersion; }
     p2p::CapDesc descriptor() const override { return {name(), version()}; }
     unsigned messageCount() const override { return PacketCount; }
+    char const* packetTypeToString(unsigned _packetType) const override
+    {
+        return ethPacketTypeToString(static_cast<EthSubprotocolPacketType>(_packetType));
+    }
     std::chrono::milliseconds backgroundWorkInterval() const override;
 
     unsigned protocolVersion() const { return c_protocolVersion; }

libethereum/EthereumPeer.cpp

@@ -134,7 +134,7 @@ void EthereumPeer::requestReceipts(h256s const& _blocks)
 }
 
 void EthereumPeer::requestByHashes(
-    h256s const& _hashes, Asking _asking, SubprotocolPacketType _packetType)
+    h256s const& _hashes, Asking _asking, EthSubprotocolPacketType _packetType)
 {
     if (m_asking != Asking::Nothing)
     {

libethereum/EthereumPeer.h

@@ -91,7 +91,8 @@ class EthereumPeer
 
 private:
     // Request of type _packetType with _hashes as input parameters
-    void requestByHashes(h256s const& _hashes, Asking _asking, SubprotocolPacketType _packetType);
+    void requestByHashes(
+        h256s const& _hashes, Asking _asking, EthSubprotocolPacketType _packetType);
 
     std::shared_ptr<p2p::CapabilityHostFace> m_host;
 

libethereum/WarpCapability.cpp

@@ -16,9 +16,28 @@ namespace eth
 
 std::chrono::milliseconds constexpr WarpCapability::c_backgroundWorkInterval;
 
+char const* warpPacketTypeToString(WarpSubprotocolPacketType _packetType)
+{
+    switch (_packetType)
+    {
+    case WarpStatusPacket:
+        return "WarpStatus";
+    case GetSnapshotManifestPacket:
+        return "GetSnapshotManifest";
+    case SnapshotManifestPacket:
+        return "SnapshotManifest";
+    case GetSnapshotDataPacket:
+        return "GetSnapshotData";
+    case SnapshotDataPacket:
+        return "SnapshotData";
+    default:
+        return "UnknownWarpPacket";
+    }
+}
+
 namespace
 {
-static size_t const c_freePeerBufferSize = 32;
+constexpr size_t c_freePeerBufferSize = 32;
 
 bool validateManifest(RLP const& _manifestRlp)
 {
@@ -380,26 +399,26 @@ bool WarpCapability::interpretCapabilityPacket(NodeID const& _peerID, unsigned _
             m_peerObserver->onPeerStatus(_peerID);
             break;
         }
-        case GetSnapshotManifest:
+        case GetSnapshotManifestPacket:
         {
             if (!m_snapshot)
                 return false;
 
             RLPStream s;
-            m_host->prep(_peerID, name(), s, SnapshotManifest, 1)
+            m_host->prep(_peerID, name(), s, SnapshotManifestPacket, 1)
                 .appendRaw(m_snapshot->readManifest());
             m_host->sealAndSend(_peerID, s);
             break;
         }
-        case GetSnapshotData:
+        case GetSnapshotDataPacket:
         {
             if (!m_snapshot)
                 return false;
 
             const h256 chunkHash = _r[0].toHash<h256>(RLP::VeryStrict);
 
             RLPStream s;
-            m_host->prep(_peerID, name(), s, SnapshotData, 1)
+            m_host->prep(_peerID, name(), s, SnapshotDataPacket, 1)
                 .append(m_snapshot->readCompressedChunk(chunkHash));
             m_host->sealAndSend(_peerID, s);
             break;
@@ -418,13 +437,13 @@ bool WarpCapability::interpretCapabilityPacket(NodeID const& _peerID, unsigned _
             m_peerObserver->onPeerBlockHeaders(_peerID, _r);
             break;
         }
-        case SnapshotManifest:
+        case SnapshotManifestPacket:
         {
             setIdle(_peerID);
             m_peerObserver->onPeerManifest(_peerID, _r);
             break;
         }
-        case SnapshotData:
+        case SnapshotDataPacket:
         {
             setIdle(_peerID);
             m_peerObserver->onPeerData(_peerID, _r);
@@ -503,7 +522,7 @@ void WarpCapability::requestManifest(NodeID const& _peerID)
     assert(itPeerStatus->second.m_asking == Asking::Nothing);
     setAsking(_peerID, Asking::WarpManifest);
     RLPStream s;
-    m_host->prep(_peerID, name(), s, GetSnapshotManifest);
+    m_host->prep(_peerID, name(), s, GetSnapshotManifestPacket);
     m_host->sealAndSend(_peerID, s);
 }
 
@@ -517,7 +536,7 @@ bool WarpCapability::requestData(NodeID const& _peerID, h256 const& _chunkHash)
     setAsking(_peerID, Asking::WarpData);
     RLPStream s;
 
-    m_host->prep(_peerID, name(), s, GetSnapshotData, 1) << _chunkHash;
+    m_host->prep(_peerID, name(), s, GetSnapshotDataPacket, 1) << _chunkHash;
     m_host->sealAndSend(_peerID, s);
     return true;
 }

libethereum/WarpCapability.h

@@ -14,19 +14,21 @@ namespace eth
 {
 class SnapshotStorageFace;
 
-unsigned const c_WarpProtocolVersion = 1;
+constexpr unsigned c_WarpProtocolVersion = 1;
 
 enum WarpSubprotocolPacketType : byte
 {
     WarpStatusPacket = 0x00,
-    GetSnapshotManifest = 0x11,
-    SnapshotManifest = 0x12,
-    GetSnapshotData = 0x13,
-    SnapshotData = 0x14,
+    GetSnapshotManifestPacket = 0x11,
+    SnapshotManifestPacket = 0x12,
+    GetSnapshotDataPacket = 0x13,
+    SnapshotDataPacket = 0x14,
 
     WarpSubprotocolPacketCount
 };
 
+char const* warpPacketTypeToString(WarpSubprotocolPacketType _packetType);
+
 struct WarpPeerStatus
 {
     /// Peer's protocol version.
@@ -77,6 +79,10 @@ class WarpCapability : public p2p::CapabilityFace
     unsigned version() const override { return c_WarpProtocolVersion; }
     p2p::CapDesc descriptor() const override { return {name(), version()}; }
     unsigned messageCount() const override { return WarpSubprotocolPacketCount; }
+    char const* packetTypeToString(unsigned _packetType) const override
+    {
+        return warpPacketTypeToString(static_cast<WarpSubprotocolPacketType>(_packetType));
+    }
     std::chrono::milliseconds backgroundWorkInterval() const override;
 
     u256 networkId() const { return m_networkId; }

libp2p/Capability.h

@@ -29,6 +29,8 @@ class CapabilityFace
     virtual CapDesc descriptor() const = 0;
     /// Number of messages supported by the subprotocol version.
     virtual unsigned messageCount() const = 0;
+    /// Convert supplied packet type to string - used for logging purposes
+    virtual char const* packetTypeToString(unsigned _packetType) const = 0;
     /// Time interval to run the background work loop at
     virtual std::chrono::milliseconds backgroundWorkInterval() const = 0;
     /// Called by the Host when new peer is connected.

libp2p/Common.cpp

@@ -15,24 +15,20 @@ using namespace std;
 const NodeIPEndpoint UnspecifiedNodeIPEndpoint = NodeIPEndpoint{{}, 0, 0};
 const Node UnspecifiedNode = Node{{}, UnspecifiedNodeIPEndpoint};
 
-char const* packetTypeToString(PacketType _packetType)
+char const* p2pPacketTypeToString(P2pPacketType _packetType)
 {
     switch (_packetType)
     {
     case HelloPacket:
-        return "HelloPacket";
+        return "Hello";
     case DisconnectPacket:
-        return "DisconnectPacket";
+        return "Disconnect";
     case PingPacket:
-        return "PingPacket";
+        return "Ping";
     case PongPacket:
-        return "PongPacket";
-    case GetPeersPacket:
-        return "GetPeersPacket";
-    case PeersPacket:
-        return "PeersPacket";
+        return "Pong";
     default:
-        return "UnknownPacket";
+        return "Unknown";
     }
 }
 

libp2p/Common.h

@@ -78,18 +78,16 @@ NET_GLOBAL_LOGGER(netlog, VerbosityDebug)
 NET_GLOBAL_LOGGER(netdetails, VerbosityTrace)
 #define cnetdetails LOG(dev::p2p::g_netdetailsLogger::get())
 
-enum PacketType
+enum P2pPacketType
 {
     HelloPacket = 0,
     DisconnectPacket,
     PingPacket,
     PongPacket,
-    GetPeersPacket,
-    PeersPacket,
     UserPacket = 0x10
 };
 
-char const* packetTypeToString(PacketType _packetType);
+char const* p2pPacketTypeToString(P2pPacketType _packetType);
 
 enum DisconnectReason
 {

libp2p/Host.cpp

@@ -261,8 +261,10 @@ void Host::doneWorking()
     m_sessions.clear();
 }
 
-// called after successful handshake
-void Host::startPeerSession(Public const& _id, RLP const& _rlp, unique_ptr<RLPXFrameCoder>&& _io, shared_ptr<RLPXSocket> const& _s)
+// Starts a new peer session after a successful handshake - agree on mutually-supported capablities,
+// start each mutually-supported capability, and send a ping to the node.
+void Host::startPeerSession(Public const& _id, RLP const& _hello,
+    unique_ptr<RLPXFrameCoder>&& _io, shared_ptr<RLPXSocket> const& _s)
 {
     // session maybe ingress or egress so m_peers and node table entries may not exist
     shared_ptr<Peer> peer;
@@ -287,11 +289,11 @@ void Host::startPeerSession(Public const& _id, RLP const& _rlp, unique_ptr<RLPXF
         peer->m_lastConnected = chrono::system_clock::now();
     peer->endpoint.setAddress(_s->remoteEndpoint().address());
 
-    auto protocolVersion = _rlp[0].toInt<unsigned>();
-    auto clientVersion = _rlp[1].toString();
-    auto caps = _rlp[2].toVector<CapDesc>();
-    auto listenPort = _rlp[3].toInt<unsigned short>();
-    auto pub = _rlp[4].toHash<Public>();
+    auto const protocolVersion = _hello[0].toInt<unsigned>();
+    auto const clientVersion = _hello[1].toString();
+    auto caps = _hello[2].toVector<CapDesc>();
+    auto const listenPort = _hello[3].toInt<unsigned short>();
+    auto const pub = _hello[4].toHash<Public>();
 
     if (pub != _id)
     {
@@ -309,13 +311,14 @@ void Host::startPeerSession(Public const& _id, RLP const& _rlp, unique_ptr<RLPXF
     for (auto cap: caps)
         capslog << "(" << cap.first << "," << dec << cap.second << ")";
 
-    cnetlog << "Hello: " << clientVersion << " V[" << protocolVersion << "]"
+    cnetlog << "Starting peer session with " << clientVersion << " V[" << protocolVersion << "]"
             << " " << _id << " " << showbase << capslog.str() << " " << dec << listenPort;
 
     // create session so disconnects are managed
     shared_ptr<SessionFace> session = make_shared<Session>(this, move(_io), _s, peer,
         PeerSessionInfo({_id, clientVersion, peer->endpoint.address().to_string(), listenPort,
-            chrono::steady_clock::duration(), _rlp[2].toSet<CapDesc>(), map<string, string>()}));
+            chrono::steady_clock::duration(), _hello[2].toSet<CapDesc>(),
+            map<string, string>()}));
     if (protocolVersion < dev::p2p::c_protocolVersion - 1)
     {
         session->disconnect(IncompatibleProtocol);
@@ -368,7 +371,8 @@ void Host::startPeerSession(Public const& _id, RLP const& _rlp, unique_ptr<RLPXF
             auto capability = itCap->second.capability;
             session->registerCapability(capDesc, offset, capability);
 
-            cnetlog << "New session for capability " << capDesc.first << "; idOffset: " << offset;
+            cnetlog << "New session for capability " << capDesc.first << "; idOffset: " << offset
+                    << " with " << _id << "@" << _s->remoteEndpoint();
 
             capability->onConnect(_id, capDesc.second);
 
@@ -377,8 +381,9 @@ void Host::startPeerSession(Public const& _id, RLP const& _rlp, unique_ptr<RLPXF
 
         session->start();
     }
-
-    LOG(m_logger) << "p2p.host.peer.register " << _id;
+
+    LOG(m_logger) << "Peer connection successfully established with " << _id << "@"
+                  << _s->remoteEndpoint();
 }
 
 void Host::onNodeTableEvent(NodeID const& _n, NodeTableEventType const& _e)
@@ -657,7 +662,7 @@ void Host::connect(shared_ptr<Peer> const& _p)
     _p->m_lastAttempted = chrono::system_clock::now();
 
     bi::tcp::endpoint ep(_p->endpoint);
-    cnetdetails << "Attempting connection to node " << _p->id << "@" << ep << " from " << id();
+    cnetdetails << "Attempting connection to " << _p->id << "@" << ep << " from " << id();
     auto socket = make_shared<RLPXSocket>(m_ioService);
     socket->ref().async_connect(ep, [=](boost::system::error_code const& ec)
     {
@@ -673,7 +678,7 @@ void Host::connect(shared_ptr<Peer> const& _p)
         }
         else
         {
-            cnetdetails << "Connecting to " << _p->id << "@" << ep;
+            cnetdetails << "Starting RLPX handshake with " << _p->id << "@" << ep;
             auto handshake = make_shared<RLPXHandshake>(this, socket, _p->id);
             {
                 Guard l(x_connecting);

libp2p/Host.h

@@ -204,7 +204,8 @@ class Host: public Worker
     bool haveNetwork() const { return m_run; }
 
     /// Validates and starts peer session, taking ownership of _io. Disconnects and returns false upon error.
-    void startPeerSession(Public const& _id, RLP const& _hello, std::unique_ptr<RLPXFrameCoder>&& _io, std::shared_ptr<RLPXSocket> const& _s);
+    void startPeerSession(Public const& _id, RLP const& _hello,
+        std::unique_ptr<RLPXFrameCoder>&& _io, std::shared_ptr<RLPXSocket> const& _s);
 
     /// Get session by id
     std::shared_ptr<SessionFace> peerSession(NodeID const& _id) const