net: Make stale tip check time type-safe, extend test

MarcoFalke · MarcoFalke · commit fa579ee742e6 · 2020-04-09T01:42:42.000+08:00
* GetTime is the non-type-safe and deprecated version of GetTime&lt;&gt;
* Extend test with ASSERT_DEBUG_LOG
* Extend test with case where a block is in flight from a node that is
  about to be evicted
diff --git a/src/net_processing.cpp b/src/net_processing.cpp
@@ -50,12 +50,12 @@ static constexpr int64_t HEADERS_DOWNLOAD_TIMEOUT_PER_HEADER = 1000; // 1ms/head
 static constexpr int32_t MAX_OUTBOUND_PEERS_TO_PROTECT_FROM_DISCONNECT = 4;
 /** Timeout for (unprotected) outbound peers to sync to our chainwork, in seconds */
 static constexpr int64_t CHAIN_SYNC_TIMEOUT = 20 * 60; // 20 minutes
-/** How frequently to check for stale tips, in seconds */
-static constexpr int64_t STALE_CHECK_INTERVAL = 10 * 60; // 10 minutes
-/** How frequently to check for extra outbound peers and disconnect, in seconds */
-static constexpr int64_t EXTRA_PEER_CHECK_INTERVAL = 45;
-/** Minimum time an outbound-peer-eviction candidate must be connected for, in order to evict, in seconds */
-static constexpr int64_t MINIMUM_CONNECT_TIME = 30;
+/** How frequently to check for stale tips */
+static constexpr std::chrono::minutes STALE_CHECK_INTERVAL{10};
+/** How frequently to check for extra outbound peers and disconnect */
+static constexpr std::chrono::seconds EXTRA_PEER_CHECK_INTERVAL{45};
+/** Minimum time an outbound-peer-eviction candidate must be connected for, in order to evict */
+static constexpr std::chrono::seconds MINIMUM_CONNECT_TIME{30};
 /** SHA256("main address relay")[0:8] */
 static constexpr uint64_t RANDOMIZER_ID_ADDRESS_RELAY = 0x3cac0035b5866b90ULL;
 /// Age after which a stale block will no longer be served if requested as
@@ -177,7 +177,7 @@ namespace {
     int g_outbound_peers_with_protect_from_disconnect GUARDED_BY(cs_main) = 0;
 
     /** When our tip was last updated. */
-    std::atomic<int64_t> g_last_tip_update(0);
+    std::atomic<std::chrono::seconds> g_last_tip_update{std::chrono::seconds{0}};
 
     /** Relay map */
     typedef std::map<uint256, CTransactionRef> MapRelay;
@@ -578,10 +578,10 @@ static void MaybeSetPeerAsAnnouncingHeaderAndIDs(NodeId nodeid, CConnman* connma
 static bool TipMayBeStale(const Consensus::Params &consensusParams) EXCLUSIVE_LOCKS_REQUIRED(cs_main)
 {
     AssertLockHeld(cs_main);
-    if (g_last_tip_update == 0) {
-        g_last_tip_update = GetTime();
+    if (g_last_tip_update.load().count() == 0) {
+        g_last_tip_update = GetTime<std::chrono::seconds>();
     }
-    return g_last_tip_update < GetTime() - consensusParams.nPowTargetSpacing * 3 && mapBlocksInFlight.empty();
+    return g_last_tip_update.load() < GetTime<std::chrono::seconds>() - std::chrono::seconds{consensusParams.nPowTargetSpacing} * 3 && mapBlocksInFlight.empty();
 }
 
 static bool CanDirectFetch(const Consensus::Params &consensusParams) EXCLUSIVE_LOCKS_REQUIRED(cs_main)
@@ -758,6 +758,7 @@ void UpdateLastBlockAnnounceTime(NodeId node, int64_t time_in_seconds)
     LOCK(cs_main);
     CNodeState *state = State(node);
     if (state) state->m_last_block_announcement = time_in_seconds;
+    if (state) state->fHaveWitness = true;
 }
 
 // Returns true for outbound peers, excluding manual connections, feelers, and
@@ -1127,7 +1128,7 @@ PeerLogicValidation::PeerLogicValidation(CConnman* connmanIn, BanMan* banman, CS
     // combine them in one function and schedule at the quicker (peer-eviction)
     // timer.
     static_assert(EXTRA_PEER_CHECK_INTERVAL < STALE_CHECK_INTERVAL, "peer eviction timer should be less than stale tip check timer");
-    scheduler.scheduleEvery([this, consensusParams] { this->CheckForStaleTipAndEvictPeers(consensusParams); }, std::chrono::seconds{EXTRA_PEER_CHECK_INTERVAL});
+    scheduler.scheduleEvery([this, consensusParams] { this->CheckForStaleTipAndEvictPeers(consensusParams); }, EXTRA_PEER_CHECK_INTERVAL);
 }
 
 /**
@@ -1165,7 +1166,7 @@ void PeerLogicValidation::BlockConnected(const std::shared_ptr<const CBlock>& pb
             LogPrint(BCLog::MEMPOOL, "Erased %d orphan tx included or conflicted by block\n", nErased);
         }
 
-        g_last_tip_update = GetTime();
+        g_last_tip_update = GetTime<std::chrono::seconds>();
     }
     {
         LOCK(g_cs_recent_confirmed_transactions);
@@ -3430,7 +3431,7 @@ void PeerLogicValidation::ConsiderEviction(CNode *pto, int64_t time_in_seconds)
     }
 }
 
-void PeerLogicValidation::EvictExtraOutboundPeers(int64_t time_in_seconds)
+void PeerLogicValidation::EvictExtraOutboundPeers(std::chrono::seconds time)
 {
     // Check whether we have too many outbound peers
     int extra_peers = connman->GetExtraOutboundCount();
@@ -3467,8 +3468,8 @@ void PeerLogicValidation::EvictExtraOutboundPeers(int64_t time_in_seconds)
                 // it time for new information to have arrived.
                 // Also don't disconnect any peer we're trying to download a
                 // block from.
-                CNodeState &state = *State(pnode->GetId());
-                if (time_in_seconds - pnode->nTimeConnected > MINIMUM_CONNECT_TIME && state.nBlocksInFlight == 0) {
+                CNodeState& state = *State(pnode->GetId());
+                if (time - std::chrono::seconds{pnode->nTimeConnected} > MINIMUM_CONNECT_TIME && state.nBlocksInFlight == 0) {
                     LogPrint(BCLog::NET, "disconnecting extra outbound peer=%d (last block announcement received at time %d)\n", pnode->GetId(), oldest_block_announcement);
                     pnode->fDisconnect = true;
                     return true;
@@ -3495,20 +3496,20 @@ void PeerLogicValidation::CheckForStaleTipAndEvictPeers(const Consensus::Params
 
     if (connman == nullptr) return;
 
-    int64_t time_in_seconds = GetTime();
+    const auto time = GetTime<std::chrono::seconds>();
 
-    EvictExtraOutboundPeers(time_in_seconds);
+    EvictExtraOutboundPeers(time);
 
-    if (time_in_seconds > m_stale_tip_check_time) {
+    if (time > m_stale_tip_check_time) {
         // Check whether our tip is stale, and if so, allow using an extra
         // outbound peer
         if (!fImporting && !fReindex && connman->GetNetworkActive() && connman->GetUseAddrmanOutgoing() && TipMayBeStale(consensusParams)) {
-            LogPrintf("Potential stale tip detected, will try using extra outbound peer (last tip update: %d seconds ago)\n", time_in_seconds - g_last_tip_update);
+            LogPrintf("Potential stale tip detected, will try using extra outbound peer (last tip update: %d seconds ago)\n", count_seconds(time - g_last_tip_update.load()));
             connman->SetTryNewOutboundPeer(true);
         } else if (connman->GetTryNewOutboundPeer()) {
             connman->SetTryNewOutboundPeer(false);
         }
-        m_stale_tip_check_time = time_in_seconds + STALE_CHECK_INTERVAL;
+        m_stale_tip_check_time = time + STALE_CHECK_INTERVAL;
     }
 }
 
diff --git a/src/net_processing.h b/src/net_processing.h
@@ -75,10 +75,10 @@ class PeerLogicValidation final : public CValidationInterface, public NetEventsI
     /** Evict extra outbound peers. If we think our tip may be stale, connect to an extra outbound */
     void CheckForStaleTipAndEvictPeers(const Consensus::Params &consensusParams);
     /** If we have extra outbound peers, try to disconnect the one with the oldest block announcement */
-    void EvictExtraOutboundPeers(int64_t time_in_seconds) EXCLUSIVE_LOCKS_REQUIRED(cs_main);
+    void EvictExtraOutboundPeers(std::chrono::seconds time) EXCLUSIVE_LOCKS_REQUIRED(cs_main);
 
 private:
-    int64_t m_stale_tip_check_time; //!< Next time to check for stale tip
+    std::chrono::seconds m_stale_tip_check_time; //!< Next time to check for stale tip
 };
 
 struct CNodeStateStats {
diff --git a/src/test/denialofservice_tests.cpp b/src/test/denialofservice_tests.cpp
@@ -8,12 +8,17 @@
 #include <chainparams.h>
 #include <net.h>
 #include <net_processing.h>
+#include <netmessagemaker.h>
+#include <pow.h>
 #include <script/sign.h>
 #include <script/signingprovider.h>
 #include <script/standard.h>
 #include <serialize.h>
+#include <test/util/logging.h>
+#include <test/util/mining.h>
 #include <test/util/net.h>
 #include <test/util/setup_common.h>
+#include <test/util/wallet.h>
 #include <util/memory.h>
 #include <util/string.h>
 #include <util/system.h>
@@ -46,7 +51,7 @@ static CService ip(uint32_t i)
 
 void UpdateLastBlockAnnounceTime(NodeId node, int64_t time_in_seconds);
 
-BOOST_FIXTURE_TEST_SUITE(denialofservice_tests, TestingSetup)
+BOOST_FIXTURE_TEST_SUITE(denialofservice_tests, RegTestingSetup)
 
 // Test eviction of an outbound peer whose chain never advances
 // Mock a node connection, and use mocktime to simulate a peer
@@ -140,6 +145,7 @@ BOOST_AUTO_TEST_CASE(stale_tip_peer_management)
     options.nMaxConnections = 125;
     options.m_max_outbound_full_relay = max_outbound_full_relay;
     options.nMaxFeeler = 1;
+    options.m_msgproc = peerLogic.get();
 
     connman->Init(options);
     std::vector<CNode *> vNodes;
@@ -156,11 +162,16 @@ BOOST_AUTO_TEST_CASE(stale_tip_peer_management)
         BOOST_CHECK(node->fDisconnect == false);
     }
 
-    SetMockTime(GetTime() + 3*consensusParams.nPowTargetSpacing + 1);
+    auto mocked_time = GetTime() + 3 * consensusParams.nPowTargetSpacing + 1;
+    SetMockTime(mocked_time);
 
     // Now tip should definitely be stale, and we should look for an extra
     // outbound peer
-    peerLogic->CheckForStaleTipAndEvictPeers(consensusParams);
+    {
+        ASSERT_DEBUG_LOG("Potential stale tip detected, will try using extra outbound peer (last tip update: 1801 seconds ago)");
+        ASSERT_DEBUG_LOG("net: setting try another outbound peer=true");
+        peerLogic->CheckForStaleTipAndEvictPeers(consensusParams);
+    }
     BOOST_CHECK(connman->GetTryNewOutboundPeer());
 
     // Still no peers should be marked for disconnection
@@ -173,7 +184,11 @@ BOOST_AUTO_TEST_CASE(stale_tip_peer_management)
     // required time connected check should be satisfied).
     AddRandomOutboundPeer(vNodes, *peerLogic, *connman);
 
-    peerLogic->CheckForStaleTipAndEvictPeers(consensusParams);
+    {
+        ASSERT_DEBUG_LOG("disconnecting extra outbound peer=8 (last block announcement received at time 0)");
+        ASSERT_DEBUG_LOG("net: setting try another outbound peer=false");
+        peerLogic->CheckForStaleTipAndEvictPeers(consensusParams);
+    }
     for (int i=0; i<max_outbound_full_relay; ++i) {
         BOOST_CHECK(vNodes[i]->fDisconnect == false);
     }
@@ -186,13 +201,64 @@ BOOST_AUTO_TEST_CASE(stale_tip_peer_management)
     // peer, and check that the next newest node gets evicted.
     UpdateLastBlockAnnounceTime(vNodes.back()->GetId(), GetTime());
 
-    peerLogic->CheckForStaleTipAndEvictPeers(consensusParams);
+    {
+        ASSERT_DEBUG_LOG("disconnecting extra outbound peer=7 (last block announcement received at time 0)");
+        ASSERT_DEBUG_LOG("net: setting try another outbound peer=false");
+        peerLogic->CheckForStaleTipAndEvictPeers(consensusParams);
+    }
     for (int i=0; i<max_outbound_full_relay-1; ++i) {
         BOOST_CHECK(vNodes[i]->fDisconnect == false);
     }
     BOOST_CHECK(vNodes[max_outbound_full_relay-1]->fDisconnect == true);
     BOOST_CHECK(vNodes.back()->fDisconnect == false);
 
+    vNodes[max_outbound_full_relay-1]->fDisconnect = false;
+    UpdateLastBlockAnnounceTime(vNodes.back()->GetId(), 0);
+
+    // Set CanDirectFetch() to true by generating a block
+    {
+        auto block = PrepareBlock(m_node, CScript{OP_TRUE});
+        block->nTime = mocked_time;
+        SolvePow(*block);
+        ProcessNewBlock(Params(), block, true, nullptr);
+    }
+    // Last node pretends to send a block
+    std::vector<CBlock> headers;
+    {
+        {
+            LOCK(cs_main);
+            const auto tip = ::ChainActive().Tip();
+            CBlock dummy{tip->GetBlockHeader()};
+            dummy.hashPrevBlock = tip->GetBlockHash();
+            dummy.nTime = mocked_time + 1;
+            SolvePow(dummy);
+
+            headers.emplace_back(dummy);
+        }
+
+        connman->ReceiveMsgFrom(*vNodes.back(), NetMsgType::HEADERS, headers);
+
+        vNodes.back()->fPauseSend = false;
+    }
+    {
+        LogPrintTest("Check that node is protected when it pretends to have a block");
+        LOCK2(cs_main, vNodes.back()->cs_sendProcessing);
+        ASSERT_DEBUG_LOG("received: headers (82 bytes) peer=8");
+        ASSERT_DEBUG_LOG("sending getdata (37 bytes) peer=8");
+        ASSERT_DEBUG_LOG("Requesting block " + headers.front().GetHash().ToString() + " from  peer=8");
+        ASSERT_DEBUG_LOG("Protecting outbound peer=8 from eviction");
+        connman->ProcessMessagesOnce(*vNodes.back());
+    }
+    {
+        ASSERT_DEBUG_LOG("disconnecting extra outbound peer=7 (last block announcement received at time 0)");
+        ASSERT_DEBUG_LOG("net: setting try another outbound peer=false");
+        peerLogic->CheckForStaleTipAndEvictPeers(consensusParams);
+    }
+    for (int i = 0; i < max_outbound_full_relay; ++i) {
+        const bool is_8th{i == 7};
+        BOOST_CHECK(vNodes[i]->fDisconnect == is_8th);
+    }
+
     bool dummy;
     for (const CNode *node : vNodes) {
         peerLogic->FinalizeNode(node->GetId(), dummy);
diff --git a/src/test/util/logging.cpp b/src/test/util/logging.cpp
@@ -11,6 +11,8 @@
 
 #include <stdexcept>
 
+void LogPrintTest(const std::string& info) { LogPrintf("[test] %s\n", info); }
+
 DebugLogHelper::DebugLogHelper(std::string message)
     : m_message{std::move(message)}
 {
diff --git a/src/test/util/logging.h b/src/test/util/logging.h
@@ -11,6 +11,9 @@
 #include <list>
 #include <string>
 
+/** Insert log from a test */
+void LogPrintTest(const std::string& info);
+
 class DebugLogHelper
 {
     const std::string m_message;
diff --git a/src/test/util/mining.cpp b/src/test/util/mining.cpp
@@ -22,15 +22,18 @@ CTxIn generatetoaddress(const NodeContext& node, const std::string& address)
     return MineBlock(node, coinbase_script);
 }
 
-CTxIn MineBlock(const NodeContext& node, const CScript& coinbase_scriptPubKey)
+void SolvePow(CBlock& block)
 {
-    auto block = PrepareBlock(node, coinbase_scriptPubKey);
-
-    while (!CheckProofOfWork(block->GetHash(), block->nBits, Params().GetConsensus())) {
-        ++block->nNonce;
-        assert(block->nNonce);
+    while (!CheckProofOfWork(block.GetHash(), block.nBits, Params().GetConsensus())) {
+        ++block.nNonce;
+        assert(block.nNonce);
     }
+}
 
+CTxIn MineBlock(const NodeContext& node, const CScript& coinbase_scriptPubKey)
+{
+    auto block = PrepareBlock(node, coinbase_scriptPubKey);
+    SolvePow(*block);
     bool processed{ProcessNewBlock(Params(), block, true, nullptr)};
     assert(processed);
 
diff --git a/src/test/util/mining.h b/src/test/util/mining.h
@@ -13,6 +13,9 @@ class CScript;
 class CTxIn;
 struct NodeContext;
 
+/** Work on the proof-of-work puzzle */
+void SolvePow(CBlock& block);
+
 /** Returns the generated coin */
 CTxIn MineBlock(const NodeContext&, const CScript& coinbase_scriptPubKey);
 
diff --git a/src/test/util/net.h b/src/test/util/net.h
@@ -6,6 +6,7 @@
 #define BITCOIN_TEST_UTIL_NET_H
 
 #include <net.h>
+#include <netmessagemaker.h>
 
 struct ConnmanTestMsg : public CConnman {
     using CConnman::CConnman;
@@ -28,6 +29,15 @@ struct ConnmanTestMsg : public CConnman {
     void NodeReceiveMsgBytes(CNode& node, const char* pch, unsigned int nBytes, bool& complete) const;
 
     bool ReceiveMsgFrom(CNode& node, CSerializedNetMsg& ser_msg) const;
+
+    template <typename P>
+    void ReceiveMsgFrom(CNode& node, const std::string& type, const P& payload)
+    {
+        const CNetMsgMaker msg_maker(PROTOCOL_VERSION);
+        CSerializedNetMsg m_ser = msg_maker.Make(type.c_str(), payload);
+
+        assert(ReceiveMsgFrom(node, m_ser));
+    }
 };
 
 #endif // BITCOIN_TEST_UTIL_NET_H
diff --git a/src/test/util/setup_common.cpp b/src/test/util/setup_common.cpp
@@ -72,8 +72,10 @@ BasicTestingSetup::BasicTestingSetup(const std::string& chainName)
     SelectParams(chainName);
     SeedInsecureRand();
     gArgs.ForceSetArg("-printtoconsole", "0");
+    gArgs.ForceSetArg("-debug", "1");
     if (G_TEST_LOG_FUN) LogInstance().PushBackCallback(G_TEST_LOG_FUN);
     InitLogging();
+    AppInitParameterInteraction();
     LogInstance().StartLogging();
     SHA256AutoDetect();
     ECC_Start();

Original file line number	Diff line number	Diff line change
`@@ -11,6 +11,8 @@`
`11`	`11`
`12`	`12`	`#include <stdexcept>`
`13`	`13`
	`14`	`+void LogPrintTest(const std::string& info) { LogPrintf("[test] %s\n", info); }`
	`15`	`+`
`14`	`16`	`DebugLogHelper::DebugLogHelper(std::string message)`
`15`	`17`	`: m_message{std::move(message)}`
`16`	`18`	`{`
Original file line number	Diff line number	Diff line change
`@@ -11,6 +11,9 @@`
`11`	`11`	`#include <list>`
`12`	`12`	`#include <string>`
`13`	`13`
	`14`	`+/** Insert log from a test */`
	`15`	`+void LogPrintTest(const std::string& info);`
	`16`	`+`
`14`	`17`	`class DebugLogHelper`
`15`	`18`	`{`
`16`	`19`	`const std::string m_message;`