Merge pull request #5575 from ethereum/log-active-peer-info

Log active peer count and peer list

Author: halfalicious

CHANGELOG.md

@@ -5,6 +5,7 @@
 - Added: [#5537](https://github.com/ethereum/aleth/pull/5537) Creating Ethereum Node Record (ENR) at program start.
 - Added: [#5557](https://github.com/ethereum/aleth/pull/5557) Improved debug logging of full sync.
 - 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.
 - Changed: [#5559](https://github.com/ethereum/aleth/pull/5559) Update peer validation error messages.
 - Fixed: [#5562](https://github.com/ethereum/aleth/pull/5562) Don't send header request messages to peers that haven't sent us Status yet.
 - Changed: [#5568](https://github.com/ethereum/aleth/pull/5568) Improve rlpx handshake log messages and create new rlpx log channel.

libp2p/Common.h

@@ -267,6 +267,16 @@ inline std::ostream& operator<<(std::ostream& _strm, NodeID const& _id)
     return _strm;
 }
 
+inline boost::log::formatting_ostream& operator<<(
+    boost::log::formatting_ostream& _strm, PeerSessionInfo const& _peerSessionInfo)
+{
+    _strm << _peerSessionInfo.id << "|" << _peerSessionInfo.clientVersion << "|"
+          << _peerSessionInfo.host << "|" << _peerSessionInfo.port << "|";
+    for (auto const& cap : _peerSessionInfo.caps)
+        _strm << "(" << cap.first << "," << cap.second << ")";
+    return _strm;
+}
+
 /// Simple stream output for a NodeIPEndpoint.
 std::ostream& operator<<(std::ostream& _out, NodeIPEndpoint const& _ep);
 

libp2p/Host.cpp

@@ -34,6 +34,9 @@ constexpr chrono::seconds c_keepAliveTimeOut{1};
 
 /// Interval which m_runTimer is run when network is connected.
 constexpr chrono::milliseconds c_runTimerInterval{100};
+
+/// Interval at which active peer info is logged
+constexpr chrono::seconds c_logActivePeersInterval{30};
 }  // namespace
 
 HostNodeTableHandler::HostNodeTableHandler(Host& _host): m_host(_host) {}
@@ -95,7 +98,8 @@ Host::Host(
     m_alias{_secretAndENR.first},
     m_enr{_secretAndENR.second},
     m_lastPing(chrono::steady_clock::time_point::min()),
-    m_capabilityHost(createCapabilityHost(*this))
+    m_capabilityHost(createCapabilityHost(*this)),
+    m_lastPeerLogMessage(chrono::steady_clock::time_point::min())
 {
     cnetnote << "Id: " << id();
     cnetnote << "ENR: " << m_enr;
@@ -683,7 +687,7 @@ void Host::connect(shared_ptr<Peer> const& _p)
     });
 }
 
-PeerSessionInfos Host::peerSessionInfo() const
+PeerSessionInfos Host::peerSessionInfos() const
 {
     if (!m_run)
         return PeerSessionInfos();
@@ -722,6 +726,7 @@ void Host::run(boost::system::error_code const& _ec)
         m_connecting.remove_if([](weak_ptr<RLPXHandshake> h){ return h.expired(); });
 
     keepAlivePeers();
+    logActivePeers();
 
     // At this time peers will be disconnected based on natural TCP timeout.
     // disconnectLatePeers needs to be updated for the assumption that Session
@@ -841,18 +846,33 @@ void Host::keepAlivePeers()
         return;
 
     RecursiveGuard l(x_sessions);
-    for (auto it = m_sessions.begin(); it != m_sessions.end();)
-        if (auto p = it->second.lock())
-        {
-            p->ping();
-            ++it;
-        }
-        else
-            it = m_sessions.erase(it);
+    {
+        for (auto it = m_sessions.begin(); it != m_sessions.end();)
+            if (auto p = it->second.lock())
+            {
+                p->ping();
+                ++it;
+            }
+            else
+                it = m_sessions.erase(it);
+    }
 
     m_lastPing = chrono::steady_clock::now();
 }
 
+void Host::logActivePeers()
+{
+    if (!m_run || chrono::steady_clock::now() - c_logActivePeersInterval < m_lastPeerLogMessage)
+        return;
+
+    LOG(m_infoLogger) << "Active peer count: " << peerCount();
+    if (m_netConfig.discovery)
+        LOG(m_infoLogger) << "Looking for peers...";
+
+    LOG(m_detailsLogger) << "Peers: " << peerSessionInfos();
+    m_lastPeerLogMessage = chrono::steady_clock::now();
+}
+
 void Host::disconnectLatePeers()
 {
     auto now = chrono::steady_clock::now();

libp2p/Host.h

@@ -168,7 +168,7 @@ class Host: public Worker
     void setPeerStretch(unsigned _n) { m_stretchPeers = _n; }
 
     /// Get peer information.
-    PeerSessionInfos peerSessionInfo() const;
+    PeerSessionInfos peerSessionInfos() const;
 
     /// Get number of peers connected.
     size_t peerCount() const;
@@ -270,6 +270,9 @@ class Host: public Worker
     /// Ping the peers to update the latency information and disconnect peers which have timed out.
     void keepAlivePeers();
 
+    /// Log count of active peers and information about each peer
+    void logActivePeers();
+
     /// Disconnect peers which didn't respond to keepAlivePeers ping prior to c_keepAliveTimeOut.
     void disconnectLatePeers();
 
@@ -371,7 +374,13 @@ class Host: public Worker
 
     std::shared_ptr<CapabilityHostFace> m_capabilityHost;
 
+    /// When the last "active peers" message was logged - used to throttle
+    /// logging to once every c_logActivePeersInterval seconds
+    std::chrono::steady_clock::time_point m_lastPeerLogMessage;
+
     Logger m_logger{createLogger(VerbosityDebug, "net")};
+    Logger m_detailsLogger{createLogger(VerbosityTrace, "net")};
+    Logger m_infoLogger{createLogger(VerbosityInfo, "net")};
 };
 
 }

libwebthree/WebThree.cpp

@@ -80,7 +80,7 @@ std::string WebThreeDirect::composeClientVersion(std::string const& _client)
 
 std::vector<PeerSessionInfo> WebThreeDirect::peers()
 {
-    return m_net.peerSessionInfo();
+    return m_net.peerSessionInfos();
 }
 
 size_t WebThreeDirect::peerCount() const

test/unittests/libp2p/peer.cpp

@@ -274,8 +274,8 @@ BOOST_AUTO_TEST_CASE(requirePeer)
     BOOST_REQUIRE_EQUAL(host1peerCount, 1);
     BOOST_REQUIRE_EQUAL(host2peerCount, 1);
 
-    PeerSessionInfos sis1 = host1.peerSessionInfo();
-    PeerSessionInfos sis2 = host2.peerSessionInfo();
+    PeerSessionInfos sis1 = host1.peerSessionInfos();
+    PeerSessionInfos sis2 = host2.peerSessionInfos();
 
     BOOST_REQUIRE_EQUAL(sis1.size(), 1);
     BOOST_REQUIRE_EQUAL(sis2.size(), 1);