Fix transaction relay bugs introduced in #14897 and expire transactions from peer in-flight map #15834

sdaftuar commented at 12:40 AM on April 17, 2019: member

#14897 introduced several bugs that could lead to a node no longer requesting transactions from one or more of its peers. Credit to ajtowns for originally reporting many of these bugs along with an originally proposed fix in #15776.

This PR does a few things:

Fix a bug in NOTFOUND processing, where the in-flight map for a peer was keeping transactions it shouldn't
Eliminate the possibility of a memory attack on the CNodeState m_tx_process_time data structure by explicitly bounding its size
Remove entries from a peer's in-flight map after 10 minutes, so that we should always eventually resume transaction requests even if there are other bugs like the NOTFOUND one
Fix a bug relating to the coordination of request times when multiple peers announce the same transaction

The expiry mechanism added here is something we'll likely want to remove in the future, but is belt-and-suspenders for now to try to ensure we don't have other bugs that could lead to transaction relay failing due to some unforeseen conditions.

fanquake assigned fanquake on Apr 17, 2019

fanquake unassigned fanquake on Apr 17, 2019

fanquake added the label P2P on Apr 17, 2019

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

in src/net_processing.cpp:79 in 7c4e69c6dc outdated

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

gmaxwell commented at 1:01 AM on April 17, 2019:

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

ajtowns commented at 2:54 AM on April 17, 2019:

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)

ajtowns commented at 7:34 AM on April 17, 2019:

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);
            }

ajtowns commented at 5:05 AM on April 18, 2019:

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...

sdaftuar commented at 6:35 PM on April 22, 2019:

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?

sdaftuar commented at 6:43 PM on April 22, 2019:

@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...?

ajtowns commented at 6:20 AM on April 23, 2019:

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.

gmaxwell commented at 8:33 PM on May 11, 2019:

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.

in src/net_processing.cpp:3128 in 7c4e69c6dc outdated

3125 | +        vRecv >> vInv;
3126 | +        if (vInv.size() <= MAX_PEER_TX_IN_FLIGHT + MAX_BLOCKS_IN_TRANSIT_PER_PEER) {
3127 | +            for (CInv &inv : vInv) {
3128 | +                if (inv.type == MSG_TX || inv.type == MSG_WITNESS_TX) {
3129 | +                    state->m_tx_download.m_tx_announced.erase(inv.hash);
3130 | +                    state->m_tx_download.m_tx_in_flight.erase(inv.hash);

ajtowns commented at 3:16 AM on April 17, 2019:

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.

ajtowns commented at 4:51 AM on April 17, 2019:

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?

ajtowns commented at 7:58 AM on April 17, 2019:

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.

sdaftuar commented at 3:57 PM on April 22, 2019:

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.

in src/net_processing.cpp:3948 in 7c4e69c6dc outdated

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

ajtowns commented at 4:17 AM on April 17, 2019:

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.

sdaftuar commented at 6:43 PM on April 22, 2019:

Sounds good, thanks.

fanquake added this to the "Blockers" column in a project

gmaxwell commented at 6:24 AM on April 17, 2019: contributor

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

MarcoFalke commented at 12:06 PM on April 17, 2019: member

Concept ACK

Could you please update the comment in

https://github.com/bitcoin/bitcoin/blob/7c4e69c6dcde13c572888fa7d00f70157b1f32aa/src/net_processing.cpp#L1462-L1469

to say:

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

MarcoFalke added the label Needs backport on Apr 17, 2019

sdaftuar commented at 5:19 PM on April 17, 2019: member

@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 commented at 6:38 PM on April 17, 2019: member

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 commented at 9:51 PM on April 17, 2019: contributor

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 commented at 3:15 PM on April 18, 2019: member

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

Conflicts

No conflicts as of last run.

laanwj commented at 3:38 PM on April 18, 2019: member

Removing this from 0.18.0 because of #14897

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

laanwj removed the label Needs backport on Apr 18, 2019

laanwj removed this from the "Blockers" column in a project

MarcoFalke referenced this in commit 607b1b7498 on Apr 18, 2019

Improve NOTFOUND comment 218697b645

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).

23163b7593

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.

e32e08407e

sdaftuar force-pushed on Apr 26, 2019

sdaftuar force-pushed on May 3, 2019

sdaftuar commented at 8:17 PM on May 3, 2019: member

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 commented at 8:12 PM on May 11, 2019: contributor

Thanks for making progress here. Testing now.

in src/net_processing.cpp:3964 in 25f710929a outdated

3959 | +        // Eventually we should consider disconnecting peers, but this is
3960 | +        // conservative.
3961 | +        if (state.m_tx_download.m_check_expiry_timer <= nNow) {
3962 | +            for (auto it=state.m_tx_download.m_tx_in_flight.begin(); it != state.m_tx_download.m_tx_in_flight.end();) {
3963 | +                if (it->second <= nNow - TX_EXPIRY_INTERVAL) {
3964 | +                    LogPrint(BCLog::NET, "timeout of inflight tx %s from peer %d\n", it->first.ToString(), pto->GetId());

gmaxwell commented at 8:25 PM on May 11, 2019:

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

sdaftuar commented at 8:30 PM on May 28, 2019:

Done

in src/net_processing.cpp:3966 in 25f710929a outdated

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

ajtowns commented at 5:23 PM on May 14, 2019:

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

sdaftuar commented at 8:30 PM on May 28, 2019:

Thanks for the tip, but leaving this alone.

in src/net_processing.cpp:78 in 25f710929a outdated

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

jonatack commented at 4:48 PM on May 15, 2019:

Worth mentioning this applies to inflight txns?

jonatack commented at 4:51 PM on May 15, 2019:

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

sdaftuar commented at 8:30 PM on May 28, 2019:

Done and done.

jonatack commented at 4:52 PM on May 15, 2019: member

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

in src/net_processing.cpp:4001 in 25f710929a outdated

3997 | @@ -3987,14 +3998,14 @@ bool PeerLogicValidation::SendMessages(CNode* pto)
3998 |                      // up processing to happen after the download times out
3999 |                      // (with a slight delay for inbound peers, to prefer
4000 |                      // requests to outbound peers).
4001 | -                    RequestTx(&state, txid, nNow);
4002 | +                    int64_t next_process_time = CalculateTxGetDataTime(txid, nNow, !state.fPreferredDownload);

ajtowns commented at 8:29 PM on May 15, 2019:

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.

ajtowns approved

ajtowns commented at 9:28 PM on May 15, 2019: member

utACK 25f710929aa15904189587647b2a52254960ecd8

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?

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>

f635a3ba11

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.

308b76732f

sdaftuar force-pushed on May 28, 2019

sdaftuar commented at 8:30 PM on May 28, 2019: member

Addressed some nits. Old version is 15834.1

sdaftuar commented at 9:11 PM on May 28, 2019: member

If the functional test is already written, I'd run it and certainly review it as an exercise to understand it. @jonatack You can take a look at this if you'd like: https://github.com/sdaftuar/bitcoin/commit/db8fc5a2e25b6fcb08924e57f3a3a1acef6611ea

Took a bit over 30 minutes the last time I ran it.

ajtowns commented at 3:36 AM on May 29, 2019: member

utACK 308b76732f97020c86977e29c854e8e27262cf7c

jonatack commented at 1:09 PM on May 30, 2019: member

@jonatack You can take a look at this if you'd like: sdaftuar@db8fc5a

Took a bit over 30 minutes the last time I ran it.

Thanks @sdaftuar. Initial run passed in ~23 minutes.

((HEAD detached at sdaftuar/test-15834))$  test/functional/feature_tx_download.py
2019-05-30T12:38:57.455000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test_gtfeuu95
2019-05-30T12:39:07.025000Z TestFramework (INFO): Nodes are setup with balances
2019-05-30T12:52:10.085000Z TestFramework (INFO): ---> Generated txid c9d4f3abccaef1315b216a9300efb64d2c91c37dc25fa451ce8af70dae7794b0
2019-05-30T12:52:11.170000Z TestFramework (INFO): ---> Mempools synced
2019-05-30T12:52:11.171000Z TestFramework (INFO): Testing transaction requests
2019-05-30T13:01:36.534000Z TestFramework (INFO): Stopping nodes
2019-05-30T13:01:36.847000Z TestFramework (INFO): Cleaning up /tmp/bitcoin_func_test_gtfeuu95 on exit
2019-05-30T13:01:36.848000Z TestFramework (INFO): Tests successful

(Edit: 2 more runs clocked in at 23 and 22 minutes. Am reviewing code and test.)

in src/net_processing.cpp:3135 in e32e08407e outdated

3132 | +                if (inv.type == MSG_TX || inv.type == MSG_WITNESS_TX) {
3133 | +                    // If we receive a NOTFOUND message for a txid we requested, erase
3134 | +                    // it from our data structures for this peer.
3135 | +                    auto in_flight_it = state->m_tx_download.m_tx_in_flight.find(inv.hash);
3136 | +                    if (in_flight_it == state->m_tx_download.m_tx_in_flight.end()) {
3137 | +                        // Skip any further work if this is a spurious NOTFOUND

morcos commented at 3:53 PM on June 6, 2019:

This comment is slightly confusing in this PR, but I think the code logic is correct. The idea is that if the tx isn't in_flight from you then there is no reason to try erasing it from m_tx_announced, because if its in there you are still going to deal with it at some later point via m_tx_process_time

MarcoFalke commented at 11:00 AM on June 11, 2019:

re https://github.com/bitcoin/bitcoin/pull/15834/commits/e32e08407e2781d881b9da92aa06494525ddd085#r291253714:

I think "spurious" is still fine. Why would a node announce you a tx and then follow up with a NOTFOUND without any further communication with you.

sdaftuar commented at 3:27 PM on June 11, 2019:

I think the questions around why I structured the loop this way (and why I made a comment about skipping "any further work") is motivated by the additional code I plan to add in #15505. See for instance: https://github.com/bitcoin/bitcoin/pull/15505/commits/f5dbb49c8922cb26d05862b7aacf161bde8ffc5a

morcos commented at 3:53 PM on June 6, 2019: member

I reviewed the logic and tried to think through various failure modes and did a light review of the code. light ACK 308b767

in src/net_processing.cpp:3128 in e32e08407e outdated

3125 | +        // Remove the NOTFOUND transactions from the peer
3126 | +        LOCK(cs_main);
3127 | +        CNodeState *state = State(pfrom->GetId());
3128 | +        std::vector<CInv> vInv;
3129 | +        vRecv >> vInv;
3130 | +        if (vInv.size() <= MAX_PEER_TX_IN_FLIGHT + MAX_BLOCKS_IN_TRANSIT_PER_PEER) {

jamesob commented at 7:01 AM on June 10, 2019:

Was confused about why we're consulting MAX_BLOCKS_IN_TRANSIT_PER_PEER for tx-based logic, but I guess this is just to avoid wasting time reading too-long DoSy INVs?

MarcoFalke commented at 10:41 AM on June 11, 2019:

in commit e32e08407e Remove NOTFOUND transactions from in-flight data structures:

doc-nit: Maybe add a comment // We only send NOTFOUNDs for transactions, but for any peer, this message should never be larger than all in-flight inventory items?

sdaftuar commented at 3:28 PM on June 11, 2019:

Yep that is the reason I had in mind -- a peer might reasonably send us a NOTFOUND for something we sent a GETDATA for, but not more than that.

in src/net_processing.cpp:3140 in e32e08407e outdated

3137 | +                        // Skip any further work if this is a spurious NOTFOUND
3138 | +                        // message.
3139 | +                        continue;
3140 | +                    }
3141 | +                    state->m_tx_download.m_tx_in_flight.erase(in_flight_it);
3142 | +                    state->m_tx_download.m_tx_announced.erase(inv.hash);

jamesob commented at 7:08 AM on June 10, 2019:

If you care to, I think the body of this loop can be written more simply as

if (inv.type == MSG_TX || inv.type == MSG_WITNESS_TX) {
    // If we receive a NOTFOUND message for a txid we requested, erase
    // it from our data structures for this peer.
    if (state->m_tx_download.m_tx_in_flight.erase(inv.hash) > 0) {
        state->m_tx_download.m_tx_announced.erase(inv.hash);
   }
}

MarcoFalke commented at 11:02 AM on June 11, 2019:

re https://github.com/bitcoin/bitcoin/pull/15834/commits/e32e08407e2781d881b9da92aa06494525ddd085#r291901132:

Looks fine, but should keep the "spurious" comment ofc.

laanwj commented at 10:26 AM on June 10, 2019: member

Code review ACK 308b76732f97020c86977e29c854e8e27262cf7c

sdaftuar renamed this:
~~Fix NOTFOUND bug and expire getdata requests for transactions~~
Fix transaction relay bugs introduced in #14897 and expire transactions from peer in-flight map
on Jun 10, 2019

in src/net_processing.cpp:3990 in 308b76732f

3997 | @@ -3987,14 +3998,14 @@ bool PeerLogicValidation::SendMessages(CNode* pto)
3998 |                      // up processing to happen after the download times out
3999 |                      // (with a slight delay for inbound peers, to prefer
4000 |                      // requests to outbound peers).
4001 | -                    RequestTx(&state, txid, nNow);

jamesob commented at 1:32 AM on June 11, 2019:

RequestTx() does the same as the two lines below, but performs .size() checks on the tx maps and ensures the txid is in m_tx_announced. Are we not just calling that because we don't care to do those checks as belt-and-suspenders, or do we specifically want to avoid populating m_tx_announced? I guess those checks are safe to avoid given txid was already in tx_process_time, but seems like it wouldn't hurt to do them anyway.

sdaftuar commented at 3:30 PM on June 11, 2019:

RequestTx() is inappropriate here and was a bug -- see @ajtowns' comment at #15834 (review)

jamesob commented at 6:11 PM on June 11, 2019:

Oops, sorry I missed that. Thanks for the pointer.

in src/net_processing.cpp:703 in 23163b7593 outdated

 698 | @@ -699,7 +699,9 @@ void UpdateTxRequestTime(const uint256& txid, int64_t request_time) EXCLUSIVE_LO
 699 |  void RequestTx(CNodeState* state, const uint256& txid, int64_t nNow) EXCLUSIVE_LOCKS_REQUIRED(cs_main)
 700 |  {
 701 |      CNodeState::TxDownloadState& peer_download_state = state->m_tx_download;
 702 | -    if (peer_download_state.m_tx_announced.size() >= MAX_PEER_TX_ANNOUNCEMENTS || peer_download_state.m_tx_announced.count(txid)) {
 703 | +    if (peer_download_state.m_tx_announced.size() >= MAX_PEER_TX_ANNOUNCEMENTS ||
 704 | +            peer_download_state.m_tx_process_time.size() >= MAX_PEER_TX_ANNOUNCEMENTS ||

jamesob commented at 1:45 AM on June 11, 2019:

Maybe worth noting that I think m_tx_process_time is liable to outgrow m_tx_announced temporarily (e.g. we ask peer for txid, get back NOTFOUND, m_tx_announced entry immediately erased but m_tx_process_time entry hangs around until next SendMessages()) but I think this is negligible.

MarcoFalke commented at 10:34 AM on June 11, 2019:

Re https://github.com/bitcoin/bitcoin/pull/15834/commits/23163b759354b84c5a076e3e2ae6ae6338106035#r292250774:

That shouldn't matter, since something else must have gone horribly wrong when there are more than MAX_PEER_TX_ANNOUNCEMENTS == 100k.

jamesob commented at 1:49 AM on June 11, 2019: member

Concept ACK https://github.com/bitcoin/bitcoin/pull/15834/commits/308b76732f97020c86977e29c854e8e27262cf7c

Mostly clarification comments. Going to ACK after I've had a chance to try to apply the tests @ajtowns wrote in #15776 to this PR.

in src/net_processing.cpp:704 in 23163b7593 outdated

 698 | @@ -699,7 +699,9 @@ void UpdateTxRequestTime(const uint256& txid, int64_t request_time) EXCLUSIVE_LO
 699 |  void RequestTx(CNodeState* state, const uint256& txid, int64_t nNow) EXCLUSIVE_LOCKS_REQUIRED(cs_main)
 700 |  {
 701 |      CNodeState::TxDownloadState& peer_download_state = state->m_tx_download;
 702 | -    if (peer_download_state.m_tx_announced.size() >= MAX_PEER_TX_ANNOUNCEMENTS || peer_download_state.m_tx_announced.count(txid)) {
 703 | +    if (peer_download_state.m_tx_announced.size() >= MAX_PEER_TX_ANNOUNCEMENTS ||
 704 | +            peer_download_state.m_tx_process_time.size() >= MAX_PEER_TX_ANNOUNCEMENTS ||
 705 | +            peer_download_state.m_tx_announced.count(txid)) {

MarcoFalke commented at 10:10 AM on June 11, 2019:

in commit 23163b7593 Add an explicit memory bound to m_tx_process_time:

style-nit: Could remove the .count() here and add the check below: if(!insert().second) return; // already have. (This is how the code looked like in previous versions of Bitcoin Core)

in src/net_processing.cpp:3960 in f635a3ba11 outdated

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

MarcoFalke commented at 11:19 AM on June 11, 2019:

in commit f635a3ba11 Expire old entries from the in-flight tx map:

style-nit: Is it required to guard the iterator increment behind some conditions? It seems less fragile and less code to just remove both in-body iterator mangling and do a normal for-loop, by putting the increment in the for-loop header?

sdaftuar commented at 3:34 PM on June 11, 2019:

Not sure if I'm misunderstanding your question, but erasing the iterator invalidates it, so we must increment it first -- so we can't just put this in the for-loop header if on some loop iterations we erase and on others we don't.

MarcoFalke commented at 11:31 AM on June 11, 2019: member

Looks good. Left some style-nits or questions. Feel free to ignore them

ACK 308b76732f

Checked that each commit looks like an improvemnt. Didn't test or compile.

<details><summary>Show signature and timestamp</summary>

Signature:

Timestamp of file with hash 5c821e3a0cb75ceb99ce84a2ae7942c0fce5d839a5cf299b21fed396a8c333bf -

</details>

sdaftuar commented at 3:37 PM on June 11, 2019: member

Thanks for the review @jamesob and @marcofalke. I'm going to leave the nits alone for now, and if I end up having to update this PR again I'll consider taking the nits at that point.

To other reviewers, I think what this PR needs most is additional testing (eg on mainnet).

jonatack commented at 4:43 PM on June 11, 2019: member

Light ACK 308b76732f97020c86977e29c854e8e27262cf7c.

Agree with additional testing. I've been looking at mainnet logs and the functional tests at https://github.com/sdaftuar/bitcoin/commit/db8fc5a2e25b6fcb08924e57f3a3a1acef6611ea to see how they might be improved or run more quickly.

Rough breakdown of current test run times in feature_tx_download.py:

test_in_flight_max in particular is a bottleneck at generally 13-15 (up to 25) minutes
test_inv_block: between 1 and 75 seconds
test_tx_requests: also a hotspot at 9-10 minutes

After the Chaincode seminars these next couple weeks, will hopefully propose tests here or in a follow-up.

sdaftuar commented at 8:10 PM on June 11, 2019: member

One other thought for reviewers -- one thing I think we didn't consider very well when #14897 was merged is the effect this change has on the relay of dependent transactions.

As a reminder, when a batch of transactions is to be announced to a peer, bitcoind will sort the batch so that parents appear before children in the INV message. Before #14897, transactions announced by a given peer would be requested in the same order as the announcement (but it was possible for transactions announced by multiple peers to be received in an arbitrary order, of course).

When a parent arrives after a child, we must rely on the orphan map to reconstruct the chain, which is inefficient and error-prone (for anti-DoS reasons we limit the size of the orphan map, so too many orphans could lead to relay failures). Given that #14897 tries to randomize getdata requests, there is an increased potential for transactions to be fetched out of order, which could be problematic.

My understanding of this issue is that we don't randomize the order of getdata's for transactions announced for the first time by outbound peers. Consequently, my guess is that this is not too big a deal. But note that (a) our inbound peers will generally announce to us faster than our outbounds (because of the way our software biases to sending with lower poisson delays to outbound peers over inbound ones), and (b) in the future, proposals like Erlay might mean we do much more flooding over outbound links than inbound ones.

If we think this is in fact a problem, or will be in the future, then I think the easiest fix would be to not put any delay on transaction requests from an inbound peers when we're learning of a transaction for the first time. I would like to hold off on addressing this issue in this PR, which I think is a strict improvement over where we are now, but I'm mentioning it in case others are more concerned about the potential severity.

MarcoFalke commented at 8:22 PM on June 11, 2019: member

Looks like this has about 6 ACKs. Unless there are objections, this will be merged within the next couple of weeks.

I am running a node with extended logging for corner cases to see if anything obvious breaks.

jamesob commented at 8:57 PM on June 11, 2019: member

ACK 308b76732f

I've run the functional test @sdaftuar wrote (https://github.com/sdaftuar/bitcoin/commit/db8fc5a2e25b6fcb08924e57f3a3a1acef6611ea) and verified that if fails before these changes and passes when cherry-picked on top of this branch.

I compiled and ran this on mainnet for a few hours. My datadir was somewhat out of date, so this code was tested in both IBD and at tip. I watched getmempoolinfo to verify its tx count looked normal and varied within reason.

Parsing debug.log shows robust tx transmission from a variety of peers during testing. Below, the message count and peer ID are shown:

Tue 11 16:51 james/src/bitcoin 308b76732f* (308b76732f) btc
$ grep -E "got inv.*peer=" /data/bitcoin/debug.log | cut -d= -f2 | sort | uniq -c

  26258 0
   5473 1
  16966 12
  25632 2
  23609 3
  25232 6
  24553 7
  25578 8
  25732 9

Tue 11 16:51 james/src/bitcoin 308b76732f* (308b76732f) btc
$ grep -E "sending getdata.*peer=" /data/bitcoin/debug.log | cut -d= -f2 | sort | uniq -c

   2513 0
    200 1
   1010 12
   2967 2
   2124 3
   2417 6
   1761 7
   2712 8
   2661 9

Testing for a few hours doesn't rule out weird edge cases, but gives me pretty good confidence this change is fine.

jamesob commented at 9:04 PM on June 11, 2019: member

@MarcoFalke isn't there an argument for merging this sooner rather than later so that it gets wider (if not incidental) test usage before 0.19 is released?

MarcoFalke commented at 11:12 AM on June 12, 2019: member

Did some tests:

:heavy_check_mark: Race between a tx and the same tx in a block is correctly timed out:

The excerpt of the debug log shows that peer 7 relays us a tx, which is included in a block shortly after. Then peer 400 announces the tx to us, and we think it is new based on our heuristic tests. Peer 400 won't send us the tx anymore (for whatever reason), and it correctly times out on our side.

$ cat ~/.bitcoin/debug.log  | grep --extended-regexp '(98a4959bf387f385b66e81e3ee7e8d6900cd31567cbc90048eb44597540a988d|00000000000000000007f6557ae653c28b86f6346f411981b0618ea423ed5ec0 height)'
2019-06-11T20:06:14Z got inv: tx 98a4959bf387f385b66e81e3ee7e8d6900cd31567cbc90048eb44597540a988d  new peer=7
2019-06-11T20:06:14Z Requesting witness-tx 98a4959bf387f385b66e81e3ee7e8d6900cd31567cbc90048eb44597540a988d peer=7
2019-06-11T20:06:14Z AcceptToMemoryPool: peer=7: accepted 98a4959bf387f385b66e81e3ee7e8d6900cd31567cbc90048eb44597540a988d (poolsz 20531 txn, 43706 kB)
2019-06-11T20:06:16Z got inv: tx 98a4959bf387f385b66e81e3ee7e8d6900cd31567cbc90048eb44597540a988d  have peer=2
2019-06-11T20:06:17Z got inv: tx 98a4959bf387f385b66e81e3ee7e8d6900cd31567cbc90048eb44597540a988d  have peer=306
2019-06-11T20:06:17Z got inv: tx 98a4959bf387f385b66e81e3ee7e8d6900cd31567cbc90048eb44597540a988d  have peer=321
2019-06-11T20:06:18Z got inv: tx 98a4959bf387f385b66e81e3ee7e8d6900cd31567cbc90048eb44597540a988d  have peer=57
2019-06-11T20:09:52Z UpdateTip: new best=00000000000000000007f6557ae653c28b86f6346f411981b0618ea423ed5ec0 height=580289 version=0x3fffe000 log2_work=90.730011 tx=423305186 date='2019-06-11T20:09:29Z' progress=1.000000 cache=20.7MiB(155741txo) warning='39 of last 100 blocks have unexpected version'
2019-06-11T20:10:13Z received getdata for: witness-tx 98a4959bf387f385b66e81e3ee7e8d6900cd31567cbc90048eb44597540a988d peer=0
2019-06-11T20:13:34Z got inv: tx 98a4959bf387f385b66e81e3ee7e8d6900cd31567cbc90048eb44597540a988d  new peer=400
2019-06-11T20:13:36Z Requesting witness-tx 98a4959bf387f385b66e81e3ee7e8d6900cd31567cbc90048eb44597540a988d peer=400
2019-06-11T20:29:04Z timeout of inflight tx 98a4959bf387f385b66e81e3ee7e8d6900cd31567cbc90048eb44597540a988d; id 400, ua /Satoshi:0.17.1/, version 70015, addr 111.37.183.111:9685, tx_relay 1, tx_sendmempool 0, fee_filter 1000, services 000000000000040d, time_connected 972, last_tx 0, last_block 0, last_mempool 0

:heavy_check_mark: A transaction is requested after it was accepted to the mempool (and later mined into a block), due to broken orphan handling (e.g. " Improve AlreadyHave #7874 "). Those cases are then at least correctly handled via NOTFOUNDs.

$ cat ~/.bitcoin/debug.log  | grep --extended-regexp '(13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7|00000000000000000024c923fe8873778e437290e4958234922df101956fa4f4 height|e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6)'
2019-06-12T10:00:54Z got inv: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7  new peer=15
2019-06-12T10:00:54Z Requesting witness-tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7 peer=15
2019-06-12T10:00:54Z AcceptToMemoryPool: peer=15: accepted 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7 (poolsz 20535 txn, 41033 kB)
2019-06-12T10:00:55Z got inv: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7  have peer=2596
2019-06-12T10:00:55Z got inv: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7  have peer=3747
2019-06-12T10:00:55Z got inv: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7  have peer=57
2019-06-12T10:00:56Z got inv: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7  have peer=2963
2019-06-12T10:00:56Z got inv: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7  have peer=3616
2019-06-12T10:00:56Z got inv: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7  have peer=124
2019-06-12T10:00:56Z got inv: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7  have peer=3957
2019-06-12T10:00:56Z got inv: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7  have peer=1206
2019-06-12T10:00:57Z got inv: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7  have peer=4655
2019-06-12T10:00:57Z got inv: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7  have peer=4769
2019-06-12T10:00:57Z got inv: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7  have peer=4269
2019-06-12T10:00:57Z got inv: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7  have peer=4983
2019-06-12T10:00:58Z got inv: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7  have peer=4258
2019-06-12T10:00:58Z got inv: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7  have peer=4391
2019-06-12T10:00:59Z got inv: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7  have peer=4576
2019-06-12T10:00:59Z got inv: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7  have peer=1281
2019-06-12T10:01:01Z received getdata for: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7 peer=995
2019-06-12T10:01:01Z received getdata for: tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7 peer=4068
2019-06-12T10:16:04Z UpdateTip: new best=00000000000000000024c923fe8873778e437290e4958234922df101956fa4f4 height=580366 version=0x20800000 log2_work=90.731743 tx=423489088 date='2019-06-12T10:15:54Z' progress=1.000000 cache=78.5MiB(585276txo) warning='36 of last 100 blocks have unexpected version'
2019-06-12T10:35:10Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  new peer=5226
2019-06-12T10:35:11Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  new peer=3396
2019-06-12T10:35:11Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  new peer=3384
2019-06-12T10:35:11Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  new peer=4576
2019-06-12T10:35:11Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  new peer=1281
2019-06-12T10:35:12Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  new peer=19
2019-06-12T10:35:12Z Requesting witness-tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6 peer=19
2019-06-12T10:35:12Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  new peer=124
2019-06-12T10:35:12Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  new peer=7
2019-06-12T10:35:12Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  new peer=15
2019-06-12T10:35:12Z AcceptToMemoryPool: peer=19: accepted e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6 (poolsz 13361 txn, 29469 kB)
2019-06-12T10:35:12Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  have peer=3747
2019-06-12T10:35:13Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  have peer=4391
2019-06-12T10:35:13Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  have peer=4655
2019-06-12T10:35:13Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  have peer=3616
2019-06-12T10:35:13Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  have peer=4269
2019-06-12T10:35:14Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  have peer=5201
2019-06-12T10:35:14Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  have peer=2963
2019-06-12T10:35:14Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  have peer=1206
2019-06-12T10:35:15Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  have peer=57
2019-06-12T10:35:16Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  have peer=2596
2019-06-12T10:35:23Z got inv: tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6  have peer=4258
2019-06-12T10:36:12Z Requesting witness-tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6 peer=15
2019-06-12T10:36:12Z stored orphan tx e6dcc6451e35996ce4d823781196830d1731c01d9d3e0fe1683b6e38675c4bf6 (mapsz 39 outsz 80)
2019-06-12T10:36:12Z Requesting witness-tx 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7 peer=15
2019-06-12T10:36:12Z Process NOTFOUND for 13f15e0e6e0e0f19b3aa84a7c6d9715991ea5b8ccf8dad9002bee7c25b596aa7 id 15, ua /Satoshi:0.17.0.1/, version 70015, addr 34.222.37.152:8333, tx_relay 1, tx_sendmempool 0, fee_filter 1000, services 000000000000040d, time_connected 56403, last_tx 21, last_block 133, last_mempool 0

MarcoFalke commented at 11:44 AM on June 12, 2019: member

ACK 308b76732f97020c86977e29c854e8e27262cf7c (Tested two of the three bugs this pull fixes, see comment above)

<details><summary>Show signature and timestamp</summary>

Signature:

Timestamp of file with hash 3ce687f87901b51b245d165509f0c12661c46cd7d1e956e5b93c607795664650 -

</details>

MarcoFalke merged this on Jun 12, 2019

MarcoFalke closed this on Jun 12, 2019

MarcoFalke referenced this in commit f792395d13 on Jun 12, 2019

sidhujag referenced this in commit 0fe7564a41 on Jun 12, 2019

MarcoFalke referenced this in commit f3855781fd on Jun 16, 2019

jasonbcox referenced this in commit 8d1a1da709 on Dec 6, 2019

codablock referenced this in commit 74eabc23e5 on Apr 7, 2020

codablock referenced this in commit 26dec64e79 on Apr 8, 2020

jonspock referenced this in commit 95f5bd81c6 on Sep 29, 2020

jonspock referenced this in commit 5b47d32846 on Sep 29, 2020

jonspock referenced this in commit 3dfd653640 on Oct 10, 2020

ckti referenced this in commit 0333b9cdda on Mar 28, 2021

DrahtBot locked this on Dec 16, 2021