Merge #19731: net, rpc: expose nLastBlockTime/nLastTXTime as last block/last_transaction in getpeerinfo

5da9621 doc: release note for getpeerinfo last_block/last_transaction (Jon Atack)
cfef5a2 test: rpc_net.py logging and test naming improvements (Jon Atack)
21c57ba test: getpeerinfo last_block and last_transaction tests (Jon Atack)
8a560a7 rpc: expose nLastBlockTime/TXTime as getpeerinfo last_block/transaction (Jon Atack)
02fbe3a net: add nLastBlockTime/TXTime to CNodeStats, CNode::copyStats (Jon Atack)

Pull request description:

  This PR adds inbound peer eviction criteria `nLastBlockTime` and `nLastTXTime` to `CNodeStats` and `CNode::copyStats`, which then allows exposing them in the next commit as `last_transaction` and `last_block` Unix Epoch Time fields in RPC `getpeerinfo`.

  This may be useful for writing missing eviction tests. I'd also like to add `lasttx` and `lastblk` columns to the `-netinfo` dashboard as described in bitcoin/bitcoin#19643 (comment).

  Relevant discussion at the p2p irc meeting http://www.erisian.com.au/bitcoin-core-dev/log-2020-08-11.html#l-549:
  ```text
  <jonatack> i was specifically trying to observe and figure out how to test bitcoin/bitcoin#19500
  <jonatack> which made me realise that i didn't know what was going on with my peer conns in enough detail
  <jonatack> i'm running bitcoin locally with nLastBlockTime and nLastTXTime added to getpeerinfo for my peer connections dashboard
  <jonatack> sipa: is there a good reason why that (eviction criteria) data is not exposed through getpeerinfo currently?
  <sipa> jonatack: nope; i suspect just nobody ever added it
  <jonatack> sipa: thanks. will propose.
  ```

  The last commit is optional, but I think it would be good to have logging in `rpc_net.py`.

ACKs for top commit:
  jnewbery:
    Code review ACK 5da9621
  theStack:
    Code Review ACK 5da9621
  darosior:
    ACK 5da9621

Tree-SHA512: 2db164bc979c014837a676e890869a128beb7cf40114853239e7280f57e768bcb43bff6c1ea76a61556212135281863b5290b50ff9d24fce16c5b89b55d4cd70

Author: laanwj

doc/release-notes-19731.md

@@ -0,0 +1,6 @@
+Updated RPCs
+------------
+
+- The `getpeerinfo` RPC now has additional `last_block` and `last_transaction`
+  fields that return the UNIX epoch time of the last block and the last valid
+  transaction received from each peer. (#19731)

src/net.cpp

@@ -530,6 +530,8 @@ void CNode::copyStats(CNodeStats &stats, const std::vector<bool> &m_asmap)
     }
     X(nLastSend);
     X(nLastRecv);
+    X(nLastTXTime);
+    X(nLastBlockTime);
     X(nTimeConnected);
     X(nTimeOffset);
     stats.addrName = GetAddrName();

src/net.h

@@ -619,6 +619,8 @@ class CNodeStats
     bool fRelayTxes;
     int64_t nLastSend;
     int64_t nLastRecv;
+    int64_t nLastTXTime;
+    int64_t nLastBlockTime;
     int64_t nTimeConnected;
     int64_t nTimeOffset;
     std::string addrName;

src/rpc/net.cpp

@@ -100,6 +100,8 @@ static UniValue getpeerinfo(const JSONRPCRequest& request)
                             {RPCResult::Type::BOOL, "relaytxes", "Whether peer has asked us to relay transactions to it"},
                             {RPCResult::Type::NUM_TIME, "lastsend", "The " + UNIX_EPOCH_TIME + " of the last send"},
                             {RPCResult::Type::NUM_TIME, "lastrecv", "The " + UNIX_EPOCH_TIME + " of the last receive"},
+                            {RPCResult::Type::NUM_TIME, "last_transaction", "The " + UNIX_EPOCH_TIME + " of the last valid transaction received from this peer"},
+                            {RPCResult::Type::NUM_TIME, "last_block", "The " + UNIX_EPOCH_TIME + " of the last block received from this peer"},
                             {RPCResult::Type::NUM, "bytessent", "The total bytes sent"},
                             {RPCResult::Type::NUM, "bytesrecv", "The total bytes received"},
                             {RPCResult::Type::NUM_TIME, "conntime", "The " + UNIX_EPOCH_TIME + " of the connection"},
@@ -169,6 +171,8 @@ static UniValue getpeerinfo(const JSONRPCRequest& request)
         obj.pushKV("relaytxes", stats.fRelayTxes);
         obj.pushKV("lastsend", stats.nLastSend);
         obj.pushKV("lastrecv", stats.nLastRecv);
+        obj.pushKV("last_transaction", stats.nLastTXTime);
+        obj.pushKV("last_block", stats.nLastBlockTime);
         obj.pushKV("bytessent", stats.nSendBytes);
         obj.pushKV("bytesrecv", stats.nRecvBytes);
         obj.pushKV("conntime", stats.nTimeConnected);

test/functional/rpc_net.py

@@ -8,9 +8,12 @@
 """
 
 from decimal import Decimal
+from itertools import product
+import time
 
 from test_framework.test_framework import BitcoinTestFramework
 from test_framework.util import (
+    assert_approx,
     assert_equal,
     assert_greater_than_or_equal,
     assert_greater_than,
@@ -48,25 +51,27 @@ def set_test_params(self):
         self.supports_cli = False
 
     def run_test(self):
-        self.log.info('Get out of IBD for the minfeefilter test')
-        self.nodes[0].generate(1)
-        self.log.info('Connect nodes both way')
+        # Get out of IBD for the minfeefilter and getpeerinfo tests.
+        self.nodes[0].generate(101)
+        # Connect nodes both ways.
         connect_nodes(self.nodes[0], 1)
         connect_nodes(self.nodes[1], 0)
 
-        self._test_connection_count()
-        self._test_getnettotals()
-        self._test_getnetworkinfo()
-        self._test_getaddednodeinfo()
-        self._test_getpeerinfo()
+        self.test_connection_count()
+        self.test_getpeerinfo()
+        self.test_getnettotals()
+        self.test_getnetworkinfo()
+        self.test_getaddednodeinfo()
         self.test_service_flags()
-        self._test_getnodeaddresses()
+        self.test_getnodeaddresses()
 
-    def _test_connection_count(self):
-        # connect_nodes connects each node to the other
+    def test_connection_count(self):
+        self.log.info("Test getconnectioncount")
+        # After using `connect_nodes` to connect nodes 0 and 1 to each other.
         assert_equal(self.nodes[0].getconnectioncount(), 2)
 
-    def _test_getnettotals(self):
+    def test_getnettotals(self):
+        self.log.info("Test getnettotals")
         # getnettotals totalbytesrecv and totalbytessent should be
         # consistent with getpeerinfo. Since the RPC calls are not atomic,
         # and messages might have been recvd or sent between RPC calls, call
@@ -96,7 +101,8 @@ def _test_getnettotals(self):
             assert_greater_than_or_equal(after['bytesrecv_per_msg'].get('pong', 0), before['bytesrecv_per_msg'].get('pong', 0) + 32)
             assert_greater_than_or_equal(after['bytessent_per_msg'].get('ping', 0), before['bytessent_per_msg'].get('ping', 0) + 32)
 
-    def _test_getnetworkinfo(self):
+    def test_getnetworkinfo(self):
+        self.log.info("Test getnetworkinfo")
         assert_equal(self.nodes[0].getnetworkinfo()['networkactive'], True)
         assert_equal(self.nodes[0].getnetworkinfo()['connections'], 2)
 
@@ -108,7 +114,7 @@ def _test_getnetworkinfo(self):
 
         with self.nodes[0].assert_debug_log(expected_msgs=['SetNetworkActive: true\n']):
             self.nodes[0].setnetworkactive(state=True)
-        self.log.info('Connect nodes both way')
+        # Connect nodes both ways.
         connect_nodes(self.nodes[0], 1)
         connect_nodes(self.nodes[1], 0)
 
@@ -120,7 +126,8 @@ def _test_getnetworkinfo(self):
         for info in network_info:
             assert_net_servicesnames(int(info["localservices"], 0x10), info["localservicesnames"])
 
-    def _test_getaddednodeinfo(self):
+    def test_getaddednodeinfo(self):
+        self.log.info("Test getaddednodeinfo")
         assert_equal(self.nodes[0].getaddednodeinfo(), [])
         # add a node (node2) to node0
         ip_port = "127.0.0.1:{}".format(p2p_port(2))
@@ -139,8 +146,20 @@ def _test_getaddednodeinfo(self):
         # check that a non-existent node returns an error
         assert_raises_rpc_error(-24, "Node has not been added", self.nodes[0].getaddednodeinfo, '1.1.1.1')
 
-    def _test_getpeerinfo(self):
+    def test_getpeerinfo(self):
+        self.log.info("Test getpeerinfo")
+        # Create a few getpeerinfo last_block/last_transaction values.
+        if self.is_wallet_compiled():
+            self.nodes[0].sendtoaddress(self.nodes[1].getnewaddress(), 1)
+        self.nodes[1].generate(1)
+        self.sync_all()
+        time_now = int(time.time())
         peer_info = [x.getpeerinfo() for x in self.nodes]
+        # Verify last_block and last_transaction keys/values.
+        for node, peer, field in product(range(self.num_nodes), range(2), ['last_block', 'last_transaction']):
+            assert field in peer_info[node][peer].keys()
+            if peer_info[node][peer][field] != 0:
+                assert_approx(peer_info[node][peer][field], time_now, vspan=60)
         # check both sides of bidirectional connection between nodes
         # the address bound to on one side will be the source address for the other node
         assert_equal(peer_info[0][0]['addrbind'], peer_info[1][0]['addr'])
@@ -152,11 +171,13 @@ def _test_getpeerinfo(self):
             assert_net_servicesnames(int(info[0]["services"], 0x10), info[0]["servicesnames"])
 
     def test_service_flags(self):
+        self.log.info("Test service flags")
         self.nodes[0].add_p2p_connection(P2PInterface(), services=(1 << 4) | (1 << 63))
         assert_equal(['UNKNOWN[2^4]', 'UNKNOWN[2^63]'], self.nodes[0].getpeerinfo()[-1]['servicesnames'])
         self.nodes[0].disconnect_p2ps()
 
-    def _test_getnodeaddresses(self):
+    def test_getnodeaddresses(self):
+        self.log.info("Test getnodeaddresses")
         self.nodes[0].add_p2p_connection(P2PInterface())
 
         # Add some addresses to the Address Manager over RPC. Due to the way