Merge #14733: P2P: Make peer timeout configurable, speed up very slow test and ensure correct code path tested.

48b37db50 make peertimeout a debug argument, remove error message translation (Zain Iqbal Allarakhia)
8042bbfbf p2p: allow p2ptimeout to be configurable, speed up slow test (Zain Iqbal Allarakhia)

Pull request description:

  **Summary:**

  1. _Primary_: Adds a `debug_only=true` flag for peertimeout, defaults to 60 sec., the current hard-coded setting.
  2. _Secondary_: Drastically speeds up `p2p_timeout.py` test.
  3. _Secondary_: Tests that the correct code path is being tested by adding log assertions to the test.

  **Rationale:**

  - P2P timeout was hard-coded: make it explicitly specified and configurable, instead of a magic number.
  - Addresses #13518; `p2p_timeout.py` takes 4 sec. to run instead of 61 sec.
  - Makes `p2p_timeout.py` more explicit. Previously, we relied on a comment to inform us of the timeout amount being tested. Now it is specified directly in the test via passing in the new arg; `-peertimeout=3`.
  - Opens us up to testing more P2P scenarios; oftentimes slow tests are the reason we don't test.

  **Locally verified changes:**

  _With Proposed Change (4.7 sec.):_
  ```
  $ time ./test/functional/p2p_timeouts.py
  2018-11-19T00:04:19.077000Z TestFramework (INFO): Initializing test directory /tmp/testhja7g2n7
  2018-11-19T00:04:23.479000Z TestFramework (INFO): Stopping nodes
  2018-11-19T00:04:23.683000Z TestFramework (INFO): Cleaning up /tmp/testhja7g2n7 on exit
  2018-11-19T00:04:23.683000Z TestFramework (INFO): Tests successful

  real    0m4.743s
  ```

  _Currently  on master (62.8 sec.):_
  ```
  $ time ./test/functional/p2p_timeouts.py
  2018-11-19T00:06:10.948000Z TestFramework (INFO): Initializing test directory /tmp/test6mo6k21h
  2018-11-19T00:07:13.376000Z TestFramework (INFO): Stopping nodes
  2018-11-19T00:07:13.631000Z TestFramework (INFO): Cleaning up /tmp/test6mo6k21h on exit
  2018-11-19T00:07:13.631000Z TestFramework (INFO): Tests successful

  real    1m2.836s
  ```

  _Error message demonstrated for new argument `-peertimeout`:_
  ```
  $ ./bitcoind -peertimeout=-5
  ...
  Error: peertimeout cannot be configured with a negative value.
  ```

Tree-SHA512: ff7a244ebea54c4059407bf4fb86465714e6a79cef5d2bcaa22cfe831a81761aaf597ba4d5172fc2ec12266f54712216fc41b5d24849e5d9dab39ba6f09e3a2a

src/init.cpp

@@ -403,6 +403,7 @@ void SetupServerArgs()
     gArgs.AddArg("-proxyrandomize", strprintf("Randomize credentials for every proxy connection. This enables Tor stream isolation (default: %u)", DEFAULT_PROXYRANDOMIZE), false, OptionsCategory::CONNECTION);
     gArgs.AddArg("-seednode=<ip>", "Connect to a node to retrieve peer addresses, and disconnect. This option can be specified multiple times to connect to multiple nodes.", false, OptionsCategory::CONNECTION);
     gArgs.AddArg("-timeout=<n>", strprintf("Specify connection timeout in milliseconds (minimum: 1, default: %d)", DEFAULT_CONNECT_TIMEOUT), false, OptionsCategory::CONNECTION);
+    gArgs.AddArg("-peertimeout=<n>", strprintf("Specify p2p connection timeout in seconds. This option determines the amount of time a peer may be inactive before the connection to it is dropped. (minimum: 1, default: %d)", DEFAULT_PEER_CONNECT_TIMEOUT), true, OptionsCategory::CONNECTION);
     gArgs.AddArg("-torcontrol=<ip>:<port>", strprintf("Tor control port to use if onion listening enabled (default: %s)", DEFAULT_TOR_CONTROL), false, OptionsCategory::CONNECTION);
     gArgs.AddArg("-torpassword=<pass>", "Tor control port password (default: empty)", false, OptionsCategory::CONNECTION);
 #ifdef USE_UPNP
@@ -856,6 +857,7 @@ int nMaxConnections;
 int nUserMaxConnections;
 int nFD;
 ServiceFlags nLocalServices = ServiceFlags(NODE_NETWORK | NODE_NETWORK_LIMITED);
+int64_t peer_connect_timeout;
 
 } // namespace
 
@@ -1054,8 +1056,14 @@ bool AppInitParameterInteraction()
     }
 
     nConnectTimeout = gArgs.GetArg("-timeout", DEFAULT_CONNECT_TIMEOUT);
-    if (nConnectTimeout <= 0)
+    if (nConnectTimeout <= 0) {
         nConnectTimeout = DEFAULT_CONNECT_TIMEOUT;
+    }
+
+    peer_connect_timeout = gArgs.GetArg("-peertimeout", DEFAULT_PEER_CONNECT_TIMEOUT);
+    if (peer_connect_timeout <= 0) {
+        return InitError("peertimeout cannot be configured with a negative value.");
+    }
 
     if (gArgs.IsArgSet("-minrelaytxfee")) {
         CAmount n = 0;
@@ -1693,6 +1701,7 @@ bool AppInitMain(InitInterfaces& interfaces)
 
     connOptions.nMaxOutboundTimeframe = nMaxOutboundTimeframe;
     connOptions.nMaxOutboundLimit = nMaxOutboundLimit;
+    connOptions.m_peer_connect_timeout = peer_connect_timeout;
 
     for (const std::string& strBind : gArgs.GetArgs("-bind")) {
         CService addrBind;

src/net.cpp

@@ -1227,11 +1227,11 @@ void CConnman::NotifyNumConnectionsChanged()
 void CConnman::InactivityCheck(CNode *pnode)
 {
     int64_t nTime = GetSystemTimeInSeconds();
-    if (nTime - pnode->nTimeConnected > 60)
+    if (nTime - pnode->nTimeConnected > m_peer_connect_timeout)
     {
         if (pnode->nLastRecv == 0 || pnode->nLastSend == 0)
         {
-            LogPrint(BCLog::NET, "socket no message in first 60 seconds, %d %d from %d\n", pnode->nLastRecv != 0, pnode->nLastSend != 0, pnode->GetId());
+            LogPrint(BCLog::NET, "socket no message in first %i seconds, %d %d from %d\n", m_peer_connect_timeout, pnode->nLastRecv != 0, pnode->nLastSend != 0, pnode->GetId());
             pnode->fDisconnect = true;
         }
         else if (nTime - pnode->nLastSend > TIMEOUT_INTERVAL)

src/net.h

@@ -78,6 +78,8 @@ static const uint64_t DEFAULT_MAX_UPLOAD_TARGET = 0;
 static const uint64_t MAX_UPLOAD_TIMEFRAME = 60 * 60 * 24;
 /** Default for blocks only*/
 static const bool DEFAULT_BLOCKSONLY = false;
+/** -peertimeout default */
+static const int64_t DEFAULT_PEER_CONNECT_TIMEOUT = 60;
 
 static const bool DEFAULT_FORCEDNSSEED = false;
 static const size_t DEFAULT_MAXRECEIVEBUFFER = 5 * 1000;
@@ -138,6 +140,7 @@ public:
         unsigned int nReceiveFloodSize = 0;
         uint64_t nMaxOutboundTimeframe = 0;
         uint64_t nMaxOutboundLimit = 0;
+        int64_t m_peer_connect_timeout = DEFAULT_PEER_CONNECT_TIMEOUT;
         std::vector<std::string> vSeedNodes;
         std::vector<CSubNet> vWhitelistedRange;
         std::vector<CService> vBinds, vWhiteBinds;
@@ -158,6 +161,7 @@ public:
         m_msgproc = connOptions.m_msgproc;
         nSendBufferMaxSize = connOptions.nSendBufferMaxSize;
         nReceiveFloodSize = connOptions.nReceiveFloodSize;
+        m_peer_connect_timeout = connOptions.m_peer_connect_timeout;
         {
             LOCK(cs_totalBytesSent);
             nMaxOutboundTimeframe = connOptions.nMaxOutboundTimeframe;
@@ -391,6 +395,9 @@ private:
     uint64_t nMaxOutboundLimit GUARDED_BY(cs_totalBytesSent);
     uint64_t nMaxOutboundTimeframe GUARDED_BY(cs_totalBytesSent);
 
+    // P2P timeout in seconds
+    int64_t m_peer_connect_timeout;
+
     // Whitelisted ranges. Any node connecting from these is automatically
     // whitelisted (as well as those connecting to whitelisted binds).
     std::vector<CSubNet> vWhitelistedRange;

test/functional/p2p_timeouts.py

@@ -14,11 +14,11 @@
 - Wait 1 second
 - Assert that we're connected
 - Send a ping to no_verack_node and no_version_node
-- Wait 30 seconds
+- Wait 1 second
 - Assert that we're still connected
 - Send a ping to no_verack_node and no_version_node
-- Wait 31 seconds
-- Assert that we're no longer connected (timeout to receive version/verack is 60 seconds)
+- Wait 2 seconds
+- Assert that we're no longer connected (timeout to receive version/verack is 3 seconds)
 """
 
 from time import sleep
@@ -36,6 +36,8 @@ class TimeoutsTest(BitcoinTestFramework):
     def set_test_params(self):
         self.setup_clean_chain = True
         self.num_nodes = 1
+        # set timeout to receive version/verack to 3 seconds
+        self.extra_args = [["-peertimeout=3"]]
 
     def run_test(self):
         # Setup the p2p connections
@@ -52,7 +54,7 @@ class TimeoutsTest(BitcoinTestFramework):
         no_verack_node.send_message(msg_ping())
         no_version_node.send_message(msg_ping())
 
-        sleep(30)
+        sleep(1)
 
         assert "version" in no_verack_node.last_message
 
@@ -63,11 +65,17 @@ class TimeoutsTest(BitcoinTestFramework):
         no_verack_node.send_message(msg_ping())
         no_version_node.send_message(msg_ping())
 
-        sleep(31)
+        expected_timeout_logs = [
+            "version handshake timeout from 0",
+            "socket no message in first 3 seconds, 1 0 from 1",
+            "socket no message in first 3 seconds, 0 0 from 2",
+        ]
 
-        assert not no_verack_node.is_connected
-        assert not no_version_node.is_connected
-        assert not no_send_node.is_connected
+        with self.nodes[0].assert_debug_log(expected_msgs=expected_timeout_logs):
+            sleep(2)
+            assert not no_verack_node.is_connected
+            assert not no_version_node.is_connected
+            assert not no_send_node.is_connected
 
 if __name__ == '__main__':
     TimeoutsTest().main()