diff --git a/src/net_processing.cpp b/src/net_processing.cpp --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -5381,8 +5381,14 @@ // Message: getdata (transactions) // - for (const TxId &txid : - m_txrequest.GetRequestable(pto->GetId(), current_time)) { + std::vector> expired; + auto requestable = + m_txrequest.GetRequestable(pto->GetId(), current_time, &expired); + for (const auto &entry : expired) { + LogPrint(BCLog::NET, "timeout of inflight tx %s from peer=%d\n", + entry.second.ToString(), entry.first); + } + for (const TxId &txid : requestable) { if (!AlreadyHaveTx(txid, m_mempool)) { LogPrint(BCLog::NET, "Requesting tx %s peer=%d\n", txid.ToString(), pto->GetId()); diff --git a/src/test/fuzz/txrequest.cpp b/src/test/fuzz/txrequest.cpp --- a/src/test/fuzz/txrequest.cpp +++ b/src/test/fuzz/txrequest.cpp @@ -262,11 +262,13 @@ //! list of (sequence number, txid) tuples. std::vector> result; + std::vector> expected_expired; for (int txid = 0; txid < MAX_TXIDS; ++txid) { // Mark any expired REQUESTED announcements as COMPLETED. for (int peer2 = 0; peer2 < MAX_PEERS; ++peer2) { Announcement &ann2 = m_announcements[txid][peer2]; if (ann2.m_state == State::REQUESTED && ann2.m_time <= m_now) { + expected_expired.emplace_back(peer2, TXIDS[txid]); ann2.m_state = State::COMPLETED; break; } @@ -282,9 +284,13 @@ } // 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> 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()); diff --git a/src/test/txrequest_tests.cpp b/src/test/txrequest_tests.cpp --- a/src/test/txrequest_tests.cpp +++ b/src/test/txrequest_tests.cpp @@ -42,6 +42,14 @@ /** Which txids have been assigned already (to prevent reuse). */ std::set txidset; + + /** + * Which (peer, txid) 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> expired; }; std::chrono::microseconds RandomTime8s() { @@ -158,7 +166,12 @@ 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> 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; @@ -182,6 +195,26 @@ }); } + /** + * Verify that an announcement for txid 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, TxId txid) { + const auto &testname = m_testname; + auto &runner = m_runner; + runner.actions.emplace_back(m_now, [=, &runner]() { + auto it = runner.expired.find(std::pair{peer, txid}); + BOOST_CHECK_MESSAGE(it != runner.expired.end(), + "[" + testname + "] missing expiration"); + if (it != runner.expired.end()) { + runner.expired.erase(it); + } + }); + } + /** * Generate a random txid, whose priorities for certain peers are * constrained. @@ -278,6 +311,7 @@ scenario.Check(peer, {}, 0, 1, 0, "s7"); scenario.AdvanceTime(MICROSECOND); scenario.Check(peer, {}, 0, 0, 0, "s8"); + scenario.CheckExpired(peer, txid); return; } else { scenario.AdvanceTime( @@ -292,9 +326,6 @@ } } - if (InsecureRandBool()) { - scenario.AdvanceTime(RandomTime8s()); - } if (config & 4) { // The peer will go offline scenario.DisconnectedPeer(peer); @@ -558,6 +589,7 @@ scenario.Check(peer1, {}, 0, 0, 1, "r9"); // Request goes back to peer2. scenario.Check(peer2, {txid}, 1, 0, 0, "r10"); + scenario.CheckExpired(peer1, txid); // Going back does not unexpire. scenario.Check(peer1, {}, 0, 0, 1, "r11", -MICROSECOND); scenario.Check(peer2, {txid}, 1, 0, 0, "r12", -MICROSECOND); @@ -626,6 +658,7 @@ scenario.AdvanceTime(expiryA - scenario.Now()); scenario.Check(peer1, {}, 0, 0, 1, "q12"); scenario.Check(peer2, {txid2, txid1}, 2, 0, 0, "q13"); + scenario.CheckExpired(peer1, txid1); // Requesting it yet again from peer1 doesn't do anything, as it's already // COMPLETED. @@ -719,6 +752,7 @@ } BOOST_CHECK_EQUAL(runner.txrequest.Size(), 0U); + BOOST_CHECK(runner.expired.empty()); } } // namespace diff --git a/src/txrequest.h b/src/txrequest.h --- a/src/txrequest.h +++ b/src/txrequest.h @@ -177,7 +177,8 @@ * * It does the following: * - Convert all REQUESTED announcements (for all txids/peers) with - * (expiry <= now) to COMPLETED ones. + * (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 txid from a different peer @@ -193,8 +194,9 @@ * peer, and end up being requested from them, the requests will happen * in announcement order. */ - std::vector GetRequestable(NodeId peer, - std::chrono::microseconds now); + std::vector + GetRequestable(NodeId peer, std::chrono::microseconds now, + std::vector> *expired = nullptr); /** * Marks a transaction as requested, with a specified expiry. diff --git a/src/txrequest.cpp b/src/txrequest.cpp --- a/src/txrequest.cpp +++ b/src/txrequest.cpp @@ -580,7 +580,11 @@ //! 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> *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. @@ -591,6 +595,9 @@ PromoteCandidateReady(m_index.project(it)); } else if (it->GetState() == State::REQUESTED && it->m_time <= now) { + if (expired) { + expired->emplace_back(it->m_peer, it->m_txid); + } MakeCompleted(m_index.project(it)); } else { break; @@ -707,10 +714,11 @@ } //! Find the TxIds to request now from peer. - std::vector GetRequestable(NodeId peer, - std::chrono::microseconds now) { + std::vector + GetRequestable(NodeId peer, std::chrono::microseconds now, + std::vector> *expired) { // Move time. - SetTimePoint(now); + SetTimePoint(now, expired); // Find all CANDIDATE_BEST announcements for this peer. std::vector selected; @@ -896,9 +904,10 @@ m_impl->ReceivedResponse(peer, txid); } -std::vector -TxRequestTracker::GetRequestable(NodeId peer, std::chrono::microseconds now) { - return m_impl->GetRequestable(peer, now); +std::vector TxRequestTracker::GetRequestable( + NodeId peer, std::chrono::microseconds now, + std::vector> *expired) { + return m_impl->GetRequestable(peer, now, expired); } uint64_t TxRequestTracker::ComputePriority(const TxId &txid, NodeId peer,