Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix NOTFOUND bug and expire getdata requests for transactions #15834

Open
wants to merge 5 commits into
base: master
from

Conversation

Projects
None yet
8 participants
@sdaftuar
Copy link
Member

commented Apr 17, 2019

Here's a more stripped down alternative to #15776, which may be quicker to review. This backports cleanly to 0.18 and should resolve the outstanding p2p issue.

To recap - there's a bug in managing the data structures tracking transaction downloads in-flight from our peers that was introduced in #14897, specifically concerning the handling of NOTFOUND messages.

This PR fixes that bug, and it adds a general expiry mechanism (originally proposed by @ajtowns in #15776) for removing entries from the in-flight map, to add robustness in the event there are scenarios we're overlooking that might cause the in-flight data structures to fill up over time.

@fanquake fanquake assigned fanquake and unassigned fanquake Apr 17, 2019

@fanquake fanquake added the P2P label Apr 17, 2019

@fanquake fanquake added this to the 0.18.0 milestone Apr 17, 2019

@@ -75,6 +75,8 @@ static constexpr int64_t INBOUND_PEER_TX_DELAY = 2 * 1000000;
static constexpr int64_t GETDATA_TX_INTERVAL = 60 * 1000000;
/** Maximum delay (in microseconds) for transaction requests to avoid biasing some peers over others. */
static constexpr int64_t MAX_GETDATA_RANDOM_DELAY = 2 * 1000000;
/** How long to wait (in microseconds) before expiring a getdata request to a peer */
static constexpr int64_t TX_EXPIRY_INTERVAL = 10 * GETDATA_TX_INTERVAL;

This comment has been minimized.

Copy link
@gmaxwell

gmaxwell Apr 17, 2019

Member

Does the use of 10 here imply that-- assuming all peers INV a transaction to us at roughly the same time-- that we get no more robustness to transaction suppression than if we only had ten peers? If so, perhaps this should be equal to the maximum number of peers times the interval

This comment has been minimized.

Copy link
@ajtowns

ajtowns Apr 17, 2019

Contributor

No, TX_EXPIRY_INTERVAL only removes tx's that are already in the in_flight list, which means we've already sent a GETDATA for them at least TX_EXPIRY_INTERVAL microseconds ago. EDIT: (And doesn't remove them from other peers' queues, whether they've been sent a GETDATA already, or that's still pending)

This comment has been minimized.

Copy link
@ajtowns

ajtowns Apr 17, 2019

Contributor

However, I think there's another bug that causes problems here -- if you have two offers with nearby m_process_time values, then you'll hit the else clause of last_request_Time <= nNow - GETDATA_TX_INTERVAL and call RequestTx(txid) which will just return because it's already present in m_tx_announced, and then you'll clear inv.hash (ie txid) from tx_process_time, and never actually request it from that peer. So I think this also needs:

            } else {
                // This transaction is in flight from someone else; queue
                // up processing to happen after the download times out
                // (with a slight delay for inbound peers, to prefer
                // requests to outbound peers).
+               state.m_tx_download.m_tx_announced.erase(inv.hash);
                RequestTx(&state, txid, nNow);
            }

This comment has been minimized.

Copy link
@ajtowns

ajtowns Apr 18, 2019

Contributor

Oh, that only works for the request side. If we get:

 0s peer A: INV deadbeef...
 1s peer B: INV deadbeef...
 ...
 5s peer Z: INV deadbeef

and then we happen to query some unresponsive peers, we'll see:

10s: -> peer D: GETDATA deadbeef...
610s: [expired]
611s: -> peer Q: GETDATA deadbeef...
1211s: [expired]

At which point every peer will have decided "it's been >15m, I'll expire the deadbeef... tx from mapRelay, and then every node will respond with NOTFOUND for that tx...

This comment has been minimized.

Copy link
@sdaftuar

sdaftuar Apr 22, 2019

Author Member

Does the use of 10 here imply that-- assuming all peers INV a transaction to us at roughly the same time-- that we get no more robustness to transaction suppression than if we only had ten peers?

@gmaxwell I'm not sure I understand the question -- is the concern that an adversary could keep re-announcing a transaction to us, and every 10 minutes we'll retry that adversary instead of going to our other peers?

I think that does seem problematic, but since we prefer outbound peers over inbound ones, we should at least be able to query all our outbound peers before an adversary would be able to cause us to re-cycle back to them. I could, as you suggest, raise this to 125 minutes to eliminate this problem, but that seemed like an excessive time to me that we might (potentially) stop transaction relay. Of course in theory this code shouldn't really kick in except for misbehaving peers, so I don't have a strong intuition of where to set it.... Thoughts?

This comment has been minimized.

Copy link
@sdaftuar

sdaftuar Apr 22, 2019

Author Member

@ajtowns Thanks for catching that bug around RequestTx(). I'll be including a fix the next time I update this PR.

Oh, that only works for the request side. If we get:

 0s peer A: INV deadbeef...
 1s peer B: INV deadbeef...
 ...
 5s peer Z: INV deadbeef

and then we happen to query some unresponsive peers, we'll see:

10s: -> peer D: GETDATA deadbeef...
610s: [expired]
611s: -> peer Q: GETDATA deadbeef...
1211s: [expired]

At which point every peer will have decided "it's been >15m, I'll expire the deadbeef... tx from mapRelay, and then every node will respond with NOTFOUND for that tx...

I think there's a misunderstanding here. The design here is supposed to be that every 1 minute (GETDATA_TX_INTERVAL), we will send a GETDATA for a txid that we want to a new peer, while every 10 minutes (TX_EXPIRY_INTERVAL) we'll clear out the in-flight request to a peer we've asked for a given txid, to make room for asking that peer for other txid's (since we cap the in-flight size to 100). Your example makes me think that you were looking at the 10-minute timer as applying to both new requests and expiring from the data structure, which should not be the case...?

This comment has been minimized.

Copy link
@ajtowns

ajtowns Apr 23, 2019

Contributor

Yeah, I think I got the GetTxRequestTime check confused with checking whether it was inflight via another node at all, rather than just hadn't been asked for for a while.

This comment has been minimized.

Copy link
@gmaxwell

gmaxwell May 11, 2019

Member

My comment on the interval was mostly that we'll expire all past the first ten to offer to us before we ever get to them. The discussion with AJ sorted out my confusion.

for (CInv &inv : vInv) {
if (inv.type == MSG_TX || inv.type == MSG_WITNESS_TX) {
state->m_tx_download.m_tx_announced.erase(inv.hash);
state->m_tx_download.m_tx_in_flight.erase(inv.hash);

This comment has been minimized.

Copy link
@ajtowns

ajtowns Apr 17, 2019

Contributor

Maybe:

if (m_tx_in_flight.erase(hash)) {
    m_tx_announced.erase(hash);
}

Otherwise sending INV x1 x2 .. x100, then looping INV x; NOTFOUND x (without ever sending the corresponding TX message) will grow m_tx_process_time unboundedly, I think.

This comment has been minimized.

Copy link
@ajtowns

ajtowns Apr 17, 2019

Contributor

Yeah, testing confirms we can get a memory leak this way -- test node gets from 60M to 1GB resident size after about 1M INV y1..y100; NOTFOUND y1..y100 pairs, after pre-filling in_flight and process with INV x1..x5000, and suggested change keeps resident size stable at 60M.

INV y; TX ytx also unconditionally clears m_tx_announced, but that's okay because redoing INV y won't re-add it to m_tx_announced because of the AlreadyHave() check. However, doing INV y1; TX y1; INV y2; TX y2; ..; INV yN; TX yN can still cause m_tx_process_time to have N entries, though. That's a lot harder to exploit, especially with the timeout this patch adds that constrains the y1..yN to be within the 20minute period, but still maybe worth doing the same fix?

This comment has been minimized.

Copy link
@ajtowns

ajtowns Apr 17, 2019

Contributor

Might be good to call EraseTxRequest(hash); inside the if as well, so that we don't delay requesting from other peers when we've already received a NOTFOUND. Could leave that for #15505 though.

This comment has been minimized.

Copy link
@sdaftuar

sdaftuar Apr 22, 2019

Author Member

The code in #15505 is checking for entries being in the in-flight map, so I'll take that suggestion here. But I think the best way to close the door on this would be to just bound the m_tx_process_time map explicitly, so I'll do that too.

I'll leave the EraseTxRequest() call for #15505.

}
// On average, we do this check every TX_EXPIRY_INTERVAL. Randomize
// so that we're not doing this for all peers at the same time.
state.m_tx_download.m_check_expiry_timer = nNow + GetRand(2*TX_EXPIRY_INTERVAL);

This comment has been minimized.

Copy link
@ajtowns

ajtowns Apr 17, 2019

Contributor

That's a bit unpredictable, maybe nNow + TX_EXPIRY_INTERVAL/2 + GetRand(TX_EXPIRY_INTERVAL) ? Also kind of a pain to test 10 minute delays that don't consider mocktime, but whatever.

This comment has been minimized.

Copy link
@sdaftuar

sdaftuar Apr 22, 2019

Author Member

Sounds good, thanks.

@gmaxwell

This comment has been minimized.

Copy link
Member

commented Apr 17, 2019

Are we failing to dequeue txn for non-witness peers that send us witness txn that we drop?

@MarcoFalke

This comment has been minimized.

Copy link
Member

commented Apr 17, 2019

Concept ACK

Could you please update the comment in

bitcoin/src/net_processing.cpp

Lines 1462 to 1469 in 7c4e69c

// Let the peer know that we didn't find what it asked for, so it doesn't
// have to wait around forever. Currently only SPV clients actually care
// about this message: it's needed when they are recursively walking the
// dependencies of relevant unconfirmed transactions. SPV clients want to
// do that because they want to know about (and store and rebroadcast and
// risk analyze) the dependencies of transactions relevant to them, without
// having to download the entire memory pool.
connman->PushMessage(pfrom, msgMaker.Make(NetMsgType::NOTFOUND, vNotFound));

to say:

  • Why we send so many notfound. (Because of orphan handling, see #15776 (comment))
  • Remove the phrase "Currently only SPV clients actually care..."
@sdaftuar

This comment has been minimized.

Copy link
Member Author

commented Apr 17, 2019

@ajtowns Thanks for the review and good catch on those additional issues you spotted. I'll continue to work on this PR for master but I now think that we should revert this for 0.18 rather than try to make a fix and backport. Please see #15839.

@sdaftuar

This comment has been minimized.

Copy link
Member Author

commented Apr 17, 2019

Are we failing to dequeue txn for non-witness peers that send us witness txn that we drop?

@gmaxwell Not that I can see. It looks to me like the only way a peer could "send" us a transaction that doesn't get dequeued is if it fails to deserialize successfully; once we've deserialized I don't think there's a code path that would not result in updating the data structures.

@gmaxwell

This comment has been minimized.

Copy link
Member

commented Apr 17, 2019

So I don't forget: Instead of disconnecting we can make the ordering in the random fetching biased based on the size() of the INVs outstanding queue and the number of expired entries.... so hosts that INV dos us just end up de-preferred for fetching.

@DrahtBot

This comment has been minimized.

Copy link
Contributor

commented Apr 18, 2019

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

No conflicts as of last run.

@laanwj

This comment has been minimized.

Copy link
Member

commented Apr 18, 2019

Removing this from 0.18.0 because of #14897

@laanwj laanwj removed this from the 0.18.0 milestone Apr 18, 2019

@laanwj laanwj removed the Needs backport label Apr 18, 2019

@laanwj laanwj removed this from Blockers in High-priority for review Apr 18, 2019

MarcoFalke added a commit that referenced this pull request Apr 18, 2019

Merge #15839: [0.18] Revert GetData randomization change (#14897)
8602d8b Revert "Change in transaction pull scheduling to prevent InvBlock-related attacks" (Suhas Daftuar)

Pull request description:

  This is for 0.18, not master -- I propose we revert the getdata change for the 0.18 release, rather than try to continue patching it up.  It seems like we've turned up several additional bugs that slipped through initial review (see #15776, #15834), and given the potential severe consequences of these bugs I think it'd make more sense for us to delay releasing this code until 0.19.

  Since the bugfix PRs are getting review, I think we can leave #14897 in master, but we can separately discuss if it should be reverted in master as well if anyone thinks that would be more appropriate.

ACKs for commit 8602d8:

Tree-SHA512: 0389cefc1bc74ac47f87866cf3a4dcfe202740a1baa3db074137e0aa5859672d74a50a34ccdb7cf43b3a3c99ce91e4ba1fb512d04d1d383d4cc184a8ada5543f

sdaftuar and others added some commits Apr 16, 2019

Remove NOTFOUND transactions from in-flight data structures
This prevents a bug where the in-flight queue for our peers will not be
drained, resulting in not downloading any new transactions from our peers.

Thanks to ajtowns for reporting this bug.
Expire old entries from the in-flight tx map
If a peer hasn't responded to a getdata request, eventually time out the request
and remove it from the in-flight data structures.  This is to prevent any bugs in
our handling of those in-flight data structures from filling up the in-flight
map and preventing us from requesting more transactions (such as the NOTFOUND
bug, fixed in a previous commit).

Co-authored-by: Anthony Towns <aj@erisian.com.au>
Add an explicit memory bound to m_tx_process_time
Previously there was an implicit bound based on the handling of m_tx_announced,
but that approach is error-prone (particularly if we start automatically
removing things from that set).

@sdaftuar sdaftuar force-pushed the sdaftuar:2019-04-fix-getdata branch from 7c4e69c to 76fe8d0 Apr 26, 2019

Fix bug around transaction requests
If a transaction is already in-flight when a peer announces a new tx to us, we
schedule a time in the future to reconsider whether to download. At that future
time, there was a bug that would prevent transactions from being rescheduled
for potential download again (ie if the transaction was still in-flight at the
time of reconsideration, such as from some other peer). Fix this.

@sdaftuar sdaftuar force-pushed the sdaftuar:2019-04-fix-getdata branch from 76fe8d0 to 25f7109 May 3, 2019

@sdaftuar

This comment has been minimized.

Copy link
Member Author

commented May 3, 2019

I've updated this PR and believe the bugs have now been fixed. I've also got a test, but with the delays involved it takes a very long time to run (ie the test has to sit around and wait for various timeouts). I'm guessing people don't want to include a test in the test suite (even an extended test) that would take tens of minutes to complete.

Would reviewers prefer me to switch the uses of GetTimeMicros() in the logic to GetTime() so that we can mock it, and then include a functional test that uses mocktime? If such tests are viewed as too contrived then I'll skip it and leave this PR as is.

@gmaxwell

This comment has been minimized.

Copy link
Member

commented May 11, 2019

Thanks for making progress here. Testing now.

if (state.m_tx_download.m_check_expiry_timer <= nNow) {
for (auto it=state.m_tx_download.m_tx_in_flight.begin(); it != state.m_tx_download.m_tx_in_flight.end();) {
if (it->second <= nNow - TX_EXPIRY_INTERVAL) {
LogPrint(BCLog::NET, "timeout of inflight tx %s from peer %d\n", it->first.ToString(), pto->GetId());

This comment has been minimized.

Copy link
@gmaxwell

gmaxwell May 11, 2019

Member

we use peer= almost everwhere in our net logs, you're messing up my log grepping.

if (it->second <= nNow - TX_EXPIRY_INTERVAL) {
LogPrint(BCLog::NET, "timeout of inflight tx %s from peer %d\n", it->first.ToString(), pto->GetId());
state.m_tx_download.m_tx_announced.erase(it->first);
state.m_tx_download.m_tx_in_flight.erase(it++);

This comment has been minimized.

Copy link
@ajtowns

ajtowns May 14, 2019

Contributor

it = m_tx_in_flight.erase(it) should do the same thing fwiw

@jonatack
Copy link
Contributor

left a comment

If the functional test is already written, I'd run it and certainly review it as an exercise to understand it.

@@ -75,6 +75,8 @@ static constexpr int64_t INBOUND_PEER_TX_DELAY = 2 * 1000000;
static constexpr int64_t GETDATA_TX_INTERVAL = 60 * 1000000;
/** Maximum delay (in microseconds) for transaction requests to avoid biasing some peers over others. */
static constexpr int64_t MAX_GETDATA_RANDOM_DELAY = 2 * 1000000;
/** How long to wait (in microseconds) before expiring a getdata request to a peer */

This comment has been minimized.

Copy link
@jonatack

jonatack May 15, 2019

Contributor

Worth mentioning this applies to inflight txns?

This comment has been minimized.

Copy link
@jonatack

jonatack May 15, 2019

Contributor

Nit: While reviewing I found myself annotating with comments, then saw similar comments existed a few lines higher up... perhaps do the same, at least for values that don't depend on other constants?

 /** Maximum number of announced transactions from a peer */
-static constexpr int32_t MAX_PEER_TX_ANNOUNCEMENTS = 2 * MAX_INV_SZ;
+static constexpr int32_t MAX_PEER_TX_ANNOUNCEMENTS = 2 * MAX_INV_SZ; // 2 * 50,000 = 100,000
 /** How many microseconds to delay requesting transactions from inbound peers */
-static constexpr int64_t INBOUND_PEER_TX_DELAY = 2 * 1000000;
+static constexpr int64_t INBOUND_PEER_TX_DELAY = 2 * 1000000; // 2 seconds
 /** How long to wait (in microseconds) before downloading a transaction from an additional peer */
-static constexpr int64_t GETDATA_TX_INTERVAL = 60 * 1000000;
+static constexpr int64_t GETDATA_TX_INTERVAL = 60 * 1000000; // 1 minute
 /** Maximum delay (in microseconds) for transaction requests to avoid biasing some peers over others. */
-static constexpr int64_t MAX_GETDATA_RANDOM_DELAY = 2 * 1000000;
+static constexpr int64_t MAX_GETDATA_RANDOM_DELAY = 2 * 1000000; // 2 seconds
 /** How long to wait (in microseconds) before expiring a getdata request to a peer */
-static constexpr int64_t TX_EXPIRY_INTERVAL = 10 * GETDATA_TX_INTERVAL;
+static constexpr int64_t TX_EXPIRY_INTERVAL = 10 * GETDATA_TX_INTERVAL; // 10 minutes
@ajtowns
Copy link
Contributor

left a comment

utACK 25f7109

Would be good to fix the peer= nit, though.

I think changes for future PRs are:

  • log NOTFOUND messages
  • make it so there aren't as many NOTFOUND messages
  • mark peers as misbehaving if inflight tx's timeout
  • switch to mockable times for this test, and keep GetTimeMicros for durations shorter than minutes
  • actually test this behaviour / expose the queue sizes?
@@ -3987,14 +3998,14 @@ bool PeerLogicValidation::SendMessages(CNode* pto)
// up processing to happen after the download times out
// (with a slight delay for inbound peers, to prefer
// requests to outbound peers).
RequestTx(&state, txid, nNow);
int64_t next_process_time = CalculateTxGetDataTime(txid, nNow, !state.fPreferredDownload);

This comment has been minimized.

Copy link
@ajtowns

ajtowns May 15, 2019

Contributor

CalculateTxGetDataTime() recalculates last_request_time and tests it against 0 via this path which seems a bit useless, but probably cleaner this way than trying to change it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.