Report and verify expirations

src/net_processing.cpp

@@ -4488,7 +4488,13 @@ bool PeerManager::SendMessages(CNode* pto)
         //
         // Message: getdata (non-blocks)
         //
-        for (const GenTxid& gtxid : m_txrequest.GetRequestable(pto->GetId(), current_time)) {
+        std::vector<std::pair<NodeId, GenTxid>> expired;
+        auto requestable = m_txrequest.GetRequestable(pto->GetId(), current_time, &expired);
+        for (const auto& entry : expired) {
+            LogPrint(BCLog::NET, "timeout of inflight %s %s from peer=%d\n", entry.second.IsWtxid() ? "wtx" : "tx",
+                entry.second.GetHash().ToString(), entry.first);
+        }
+        for (const GenTxid& gtxid : requestable) {
             if (!AlreadyHaveTx(gtxid, m_mempool)) {
                 LogPrint(BCLog::NET, "Requesting %s %s peer=%d\n", gtxid.IsWtxid() ? "wtx" : "tx",
                     gtxid.GetHash().ToString(), pto->GetId());

src/primitives/transaction.h

@@ -399,8 +399,8 @@ template <typename Tx> static inline CTransactionRef MakeTransactionRef(Tx&& txI
 /** A generic txid reference (txid or wtxid). */
 class GenTxid
 {
-    const bool m_is_wtxid;
-    const uint256 m_hash;
+    bool m_is_wtxid;
+    uint256 m_hash;
 public:
     GenTxid(bool is_wtxid, const uint256& hash) : m_is_wtxid(is_wtxid), m_hash(hash) {}
     bool IsWtxid() const { return m_is_wtxid; }

src/test/fuzz/txrequest.cpp

@@ -246,11 +246,13 @@ class Tester
 
         //! list of (sequence number, txhash, is_wtxid) tuples.
         std::vector<std::tuple<uint64_t, int, bool>> result;
+        std::vector<std::pair<NodeId, GenTxid>> expected_expired;
         for (int txhash = 0; txhash < MAX_TXHASHES; ++txhash) {
             // Mark any expired REQUESTED announcements as COMPLETED.
             for (int peer2 = 0; peer2 < MAX_PEERS; ++peer2) {
                 Announcement& ann2 = m_announcements[txhash][peer2];
                 if (ann2.m_state == State::REQUESTED && ann2.m_time <= m_now) {
+                    expected_expired.emplace_back(peer2, GenTxid{ann2.m_is_wtxid, TXHASHES[txhash]});
                     ann2.m_state = State::COMPLETED;
                     break;
                 }
@@ -265,9 +267,13 @@ class Tester
         }
         // Sort the results by sequence number.
         std::sort(result.begin(), result.end());
+        std::sort(expected_expired.begin(), expected_expired.end());
 
         // Compare with TxRequestTracker's implementation.
-        const auto actual = m_tracker.GetRequestable(peer, m_now);
+        std::vector<std::pair<NodeId, GenTxid>> expired;
+        const auto actual = m_tracker.GetRequestable(peer, m_now, &expired);
+        std::sort(expired.begin(), expired.end());
+        assert(expired == expected_expired);
 
         m_tracker.PostGetRequestableSanityCheck(m_now);
         assert(result.size() == actual.size());

src/test/txrequest_tests.cpp

@@ -43,6 +43,11 @@ struct Runner
 
     /** Which txhashes have been assigned already (to prevent reuse). */
     std::set<uint256> txhashset;
+
+    /** Which (peer, gtxid) combinations are known to be expired. These need to be accumulated here instead of
+     *  checked directly in the GetRequestable return value to avoid introducing a dependency between the various
+     *  parallel tests. */
+    std::multiset<std::pair<NodeId, GenTxid>> expired;
 };
 
 std::chrono::microseconds RandomTime8s() { return std::chrono::microseconds{1 + InsecureRandBits(23)}; }
@@ -149,7 +154,9 @@ class Scenario
         const auto now = m_now;
         assert(offset.count() <= 0);
         runner.actions.emplace_back(m_now, [=,&runner]() {
-            auto ret = runner.txrequest.GetRequestable(peer, now + offset);
+            std::vector<std::pair<NodeId, GenTxid>> expired_now;
+            auto ret = runner.txrequest.GetRequestable(peer, now + offset, &expired_now);
+            for (const auto& entry : expired_now) runner.expired.insert(entry);
             runner.txrequest.SanityCheck();
             runner.txrequest.PostGetRequestableSanityCheck(now + offset);
             size_t total = candidates + inflight + completed;
@@ -163,6 +170,21 @@ class Scenario
         });
     }
 
+    /** Verify that an announcement for gtxid by peer has expired some time before this check is scheduled.
+     *
+     * Every expected expiration should be accounted for through exactly one call to this function.
+     */
+    void CheckExpired(NodeId peer, GenTxid gtxid)
+    {
+        const auto& testname = m_testname;
+        auto& runner = m_runner;
+        runner.actions.emplace_back(m_now, [=,&runner]() {
+            auto it = runner.expired.find(std::pair<NodeId, GenTxid>{peer, gtxid});
+            BOOST_CHECK_MESSAGE(it != runner.expired.end(), "[" + testname + "] missing expiration");
+            if (it != runner.expired.end()) runner.expired.erase(it);
+        });
+    }
+
     /** Generate a random txhash, whose priorities for certain peers are constrained.
      *
      * For example, NewTxHash({{p1,p2,p3},{p2,p4,p5}}) will generate a txhash T such that both:
@@ -256,6 +278,7 @@ void BuildSingleTest(Scenario& scenario, int config)
             scenario.Check(peer, {}, 0, 1, 0, "s7");
             scenario.AdvanceTime(MICROSECOND);
             scenario.Check(peer, {}, 0, 0, 0, "s8");
+            scenario.CheckExpired(peer, gtxid);
             return;
         } else {
             scenario.AdvanceTime(std::chrono::microseconds{InsecureRandRange(expiry.count())});
@@ -268,7 +291,6 @@ void BuildSingleTest(Scenario& scenario, int config)
         }
     }
 
-    if (InsecureRandBool()) scenario.AdvanceTime(RandomTime8s());
     if (config & 4) { // The peer will go offline
         scenario.DisconnectedPeer(peer);
     } else { // The transaction is no longer needed
@@ -519,9 +541,11 @@ void BuildWtxidTest(Scenario& scenario, int config)
     if (config & 2) {
         scenario.Check(peerT, {}, 0, 0, 1, "w9");
         scenario.Check(peerW, {wtxid}, 1, 0, 0, "w10");
+        scenario.CheckExpired(peerT, txid);
     } else {
         scenario.Check(peerT, {txid}, 1, 0, 0, "w11");
         scenario.Check(peerW, {}, 0, 0, 1, "w12");
+        scenario.CheckExpired(peerW, wtxid);
     }
 
     // If a good transaction with either that hash as wtxid or txid arrives, both
@@ -567,6 +591,7 @@ void BuildTimeBackwardsTest(Scenario& scenario)
     scenario.AdvanceTime(expiry - scenario.Now());
     scenario.Check(peer1, {}, 0, 0, 1, "r9");
     scenario.Check(peer2, {gtxid}, 1, 0, 0, "r10"); // Request goes back to peer2.
+    scenario.CheckExpired(peer1, gtxid);
     scenario.Check(peer1, {}, 0, 0, 1, "r11", -MICROSECOND); // Going back does not unexpire.
     scenario.Check(peer2, {gtxid}, 1, 0, 0, "r12", -MICROSECOND);
 
@@ -623,6 +648,7 @@ void BuildWeirdRequestsTest(Scenario& scenario)
     scenario.AdvanceTime(expiryA - scenario.Now());
     scenario.Check(peer1, {}, 0, 0, 1, "q12");
     scenario.Check(peer2, {gtxid2, gtxid1}, 2, 0, 0, "q13");
+    scenario.CheckExpired(peer1, gtxid1);
 
     // Requesting it yet again from peer1 doesn't do anything, as it's already COMPLETED.
     if (InsecureRandBool()) scenario.AdvanceTime(RandomTime8s());
@@ -697,6 +723,7 @@ void TestInterleavedScenarios()
     }
 
     BOOST_CHECK_EQUAL(runner.txrequest.Size(), 0U);
+    BOOST_CHECK(runner.expired.empty());
 }
 
 }  // namespace

src/txrequest.cpp

@@ -291,6 +291,11 @@ std::map<uint256, TxHashInfo> ComputeTxHashInfo(const Index& index, const Priori
     return ret;
 }
 
+GenTxid ToGenTxid(const Announcement& ann)
+{
+    return {ann.m_is_wtxid, ann.m_txhash};
+}
+
 }  // namespace
 
 /** Actual implementation for TxRequestTracker's data structure. */
@@ -477,15 +482,18 @@ class TxRequestTracker::Impl {
     //! - REQUESTED annoucements with expiry <= now are turned into COMPLETED.
     //! - CANDIDATE_DELAYED announcements with reqtime <= now are turned into CANDIDATE_{READY,BEST}.
     //! - CANDIDATE_{READY,BEST} announcements with reqtime > now are turned into CANDIDATE_DELAYED.
-    void SetTimePoint(std::chrono::microseconds now)
+    void SetTimePoint(std::chrono::microseconds now, std::vector<std::pair<NodeId, GenTxid>>* expired)
     {
+        if (expired) expired->clear();
+
         // Iterate over all CANDIDATE_DELAYED and REQUESTED from old to new, as long as they're in the past,
         // and convert them to CANDIDATE_READY and COMPLETED respectively.
         while (!m_index.empty()) {
             auto it = m_index.get<ByTime>().begin();
             if (it->m_state == State::CANDIDATE_DELAYED && it->m_time <= now) {
                 PromoteCandidateReady(m_index.project<ByTxHash>(it));
             } else if (it->m_state == State::REQUESTED && it->m_time <= now) {
+                if (expired) expired->emplace_back(it->m_peer, ToGenTxid(*it));
                 MakeCompleted(m_index.project<ByTxHash>(it));
             } else {
                 break;
@@ -578,10 +586,11 @@ class TxRequestTracker::Impl {
     }
 
     //! Find the GenTxids to request now from peer.
-    std::vector<GenTxid> GetRequestable(NodeId peer, std::chrono::microseconds now)
+    std::vector<GenTxid> GetRequestable(NodeId peer, std::chrono::microseconds now,
+        std::vector<std::pair<NodeId, GenTxid>>* expired)
     {
         // Move time.
-        SetTimePoint(now);
+        SetTimePoint(now, expired);
 
         // Find all CANDIDATE_BEST announcements for this peer.
         std::vector<const Announcement*> selected;
@@ -601,7 +610,7 @@ class TxRequestTracker::Impl {
         std::vector<GenTxid> ret;
         ret.reserve(selected.size());
         std::transform(selected.begin(), selected.end(), std::back_inserter(ret), [](const Announcement* ann) {
-            return GenTxid{ann->m_is_wtxid, ann->m_txhash};
+            return ToGenTxid(*ann);
         });
         return ret;
     }
@@ -727,9 +736,10 @@ void TxRequestTracker::ReceivedResponse(NodeId peer, const uint256& txhash)
     m_impl->ReceivedResponse(peer, txhash);
 }
 
-std::vector<GenTxid> TxRequestTracker::GetRequestable(NodeId peer, std::chrono::microseconds now)
+std::vector<GenTxid> TxRequestTracker::GetRequestable(NodeId peer, std::chrono::microseconds now,
+    std::vector<std::pair<NodeId, GenTxid>>* expired)
 {
-    return m_impl->GetRequestable(peer, now);
+    return m_impl->GetRequestable(peer, now, expired);
 }
 
 uint64_t TxRequestTracker::ComputePriority(const uint256& txhash, NodeId peer, bool preferred) const

src/txrequest.h

@@ -148,6 +148,7 @@ class TxRequestTracker {
      *
      * It does the following:
      *  - Convert all REQUESTED announcements (for all txhashes/peers) with (expiry <= now) to COMPLETED ones.
+     *    These are returned in expired, if non-nullptr.
      *  - Requestable announcements are selected: CANDIDATE announcements from the specified peer with
      *    (reqtime <= now) for which no existing REQUESTED announcement with the same txhash from a different peer
      *    exists, and for which the specified peer is the best choice among all (reqtime <= now) CANDIDATE
@@ -159,7 +160,8 @@ class TxRequestTracker {
      *    out of order: if multiple dependent transactions are announced simultaneously by one peer, and end up
      *    being requested from them, the requests will happen in announcement order.
      */
-    std::vector<GenTxid> GetRequestable(NodeId peer, std::chrono::microseconds now);
+    std::vector<GenTxid> GetRequestable(NodeId peer, std::chrono::microseconds now,
+        std::vector<std::pair<NodeId, GenTxid>>* expired = nullptr);
 
     /** Marks a transaction as requested, with a specified expiry.
      *