test: Add more tests for orphan tx handling #19393

hebasto commented at 10:28 AM on June 27, 2020: member

This PR adds test coverage for the following cases:

erase orphan transactions when a peer is disconnected
erase an orphan transaction when it is included in a new tip block
erase an orphan transaction when it is conflicted with other transactions included in a new tip block

Found useful while working on #19374.

fanquake added the label Tests on Jun 27, 2020

in test/functional/p2p_invalid_tx.py:96 in 10f7f75502 outdated

  92 | @@ -94,24 +93,24 @@ def run_test(self):
  93 |          SCRIPT_PUB_KEY_OP_TRUE = b'\x51\x75' * 15 + b'\x51'
  94 |          tx_withhold = CTransaction()
  95 |          tx_withhold.vin.append(CTxIn(outpoint=COutPoint(block1.vtx[0].sha256, 0)))
  96 | -        tx_withhold.vout.append(CTxOut(nValue=50 * COIN - 12000, scriptPubKey=SCRIPT_PUB_KEY_OP_TRUE))
  97 | +        tx_withhold.vout = [CTxOut(nValue=25 * COIN  - 12000, scriptPubKey=SCRIPT_PUB_KEY_OP_TRUE)] * 2

jonatack commented at 4:41 PM on June 27, 2020:

02d0b4e nit

        tx_withhold.vout = [CTxOut(nValue=25 * COIN - 12000, scriptPubKey=SCRIPT_PUB_KEY_OP_TRUE)] * 2

hebasto commented at 4:48 PM on June 28, 2020:

hmm, why python linter did not catch it?

hebasto commented at 5:17 PM on June 28, 2020:

Updated.

in test/functional/p2p_invalid_tx.py:168 in 10f7f75502 outdated

 163 |          rejected_parent.vout.append(CTxOut(nValue=11 * COIN, scriptPubKey=SCRIPT_PUB_KEY_OP_TRUE))
 164 |          rejected_parent.rehash()
 165 |          with node.assert_debug_log(['not keeping orphan with rejected parents {}'.format(rejected_parent.hash)]):
 166 |              node.p2p.send_txs_and_test([rejected_parent], node, success=False)
 167 |  
 168 | +        self.log.info('Test erase of orphan tx from peer')

jonatack commented at 12:49 PM on June 28, 2020:

48b43e2a

        self.log.info('Test disconnecting a peer logs erasure of its orphan transactions')

hebasto commented at 5:19 PM on June 28, 2020:

I'd rather leave log message as is, as working logging implies working erase a tx from the orphan pool.

hebasto commented at 6:17 PM on June 28, 2020:

Updated.

in test/functional/p2p_invalid_tx.py:172 in 10f7f75502 outdated

 167 |  
 168 | +        self.log.info('Test erase of orphan tx from peer')
 169 | +        with node.assert_debug_log(['Erased 100 orphan tx from peer=24']):
 170 | +            self.reconnect_p2p(num_connections=1)
 171 | +
 172 | +        self.log.info('Test erase of orphan tx included by block')

jonatack commented at 1:03 PM on June 28, 2020:

What is being asserted in this subtest?

hebasto commented at 4:58 PM on June 28, 2020:

What is being asserted in this subtest?

If a transaction from a new tip block is found in the orphan pool, it should be excluded from it.

jonatack commented at 5:33 PM on June 28, 2020:

Could add that info to the log message. Same with #19393 (review): state the action and expected result under test: "Test (action) causes (result)". Just my opinion, of course.

hebasto commented at 6:17 PM on June 28, 2020:

Updated.

in test/functional/p2p_invalid_tx.py:184 in 10f7f75502 outdated

 179 | +        tx_orphan_include_by_blockA.vin.append(CTxIn(outpoint=COutPoint(tx_withhold_until_blockA.sha256, 0)))
 180 | +        tx_orphan_include_by_blockA.vout.append(CTxOut(nValue=12 * COIN - 12000, scriptPubKey=SCRIPT_PUB_KEY_OP_TRUE))
 181 | +        tx_orphan_include_by_blockA.calc_sha256()
 182 | +
 183 | +        self.log.info('Send the tx_orphan_include_by_blockA ... ')
 184 | +        node.p2p.send_txs_and_test([tx_orphan_include_by_blockA], node, success=False)

jonatack commented at 1:07 PM on June 28, 2020:

This is checking the the txn is not accepted into the mempool; mind mentioning the expected outcome in the info log and why?

hebasto commented at 5:28 PM on June 28, 2020:

Re-worded. It seems mention "orphan" transaction implies that it is not accepted into the mempool, no?

in test/functional/p2p_invalid_tx.py:193 in 10f7f75502 outdated

 188 | +        blockA = create_block(tip, create_coinbase(height))
 189 | +        blockA.vtx.extend([tx_withhold, tx_withhold_until_blockA, tx_orphan_include_by_blockA])
 190 | +        blockA.hashMerkleRoot = blockA.calc_merkle_root()
 191 | +        blockA.solve()
 192 | +
 193 | +        self.log.info('Send the blockA that includes tx_orphan_include_by_blockA ... ')

jonatack commented at 1:10 PM on June 28, 2020:

Idem, mind describing the expected outcome (accepted by the mempool) and why? This log seems more cryptic than reading the test code.

hebasto commented at 5:29 PM on June 28, 2020:

Re-worded.

in test/functional/p2p_invalid_tx.py:168 in 10f7f75502 outdated

 164 |          rejected_parent.rehash()
 165 |          with node.assert_debug_log(['not keeping orphan with rejected parents {}'.format(rejected_parent.hash)]):
 166 |              node.p2p.send_txs_and_test([rejected_parent], node, success=False)
 167 |  
 168 | +        self.log.info('Test erase of orphan tx from peer')
 169 | +        with node.assert_debug_log(['Erased 100 orphan tx from peer=24']):

jonatack commented at 1:18 PM on June 28, 2020:

This test seems dependent on the context/test order. Is it possible to make it order-independent and to test for the change itself? (Ignore if not.)

hebasto commented at 5:01 PM on June 28, 2020:

This variant, i.e., the previous test state reuse, just suggests the minimum diff.

jonatack commented at 1:23 PM on June 28, 2020: member

Concept ACK.

Could say in the PR description what led you to see the need for this additional coverage.
Testing debug log output is convenient but less robust; better to test for actual change, if possible.
Readability nit: for variable names when the rest of the name is snakecased: s/blockA/block_A and s/blockB/block_B/
It would be great for the logging to state clearly what the test is asserting, the expected outcome, and why. ISTM info logging can be good at the beginning of a subtest as well as just before the key assertion(s).
If a subtest does not need the context from the previous ones, it can be good to separate it to an independent method.

hebasto commented at 3:34 PM on June 28, 2020: member

@jonatack

Could say in the PR description what led you to see the need for this additional coverage.

The OP has been updated.

Testing debug log output is convenient but less robust; better to test for actual change, if possible.

Agree. But we have neither RPC calls nor the public interface for the orphan transaction pool.

hebasto force-pushed on Jun 28, 2020

hebasto commented at 5:15 PM on June 28, 2020: member

Updated 10f7f75502bdcc9045c0623386571e41103b69fe -> a95a6d99b31798a8adb107930857bbe5c6e083df (pr19393.01 -> pr19393.02, diff):

addressed @jonatack's comments

hebasto force-pushed on Jun 28, 2020

hebasto commented at 6:16 PM on June 28, 2020: member

Updated a95a6d99b31798a8adb107930857bbe5c6e083df -> 3a310fbf1733e2ddaf1e6707251c409b287838de (pr19393.02 -> pr19393.03, diff):

addressed @jonatack's comment:

Could add that info to the log message. Same with #19393 (comment): state the action and expected result under test: "Test (action) causes (result)". Just my opinion, of course.

DrahtBot commented at 4:07 AM on August 26, 2020: member

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

Conflicts

No conflicts as of last run.

DrahtBot added the label Needs rebase on Sep 25, 2020

hebasto force-pushed on Sep 28, 2020

DrahtBot removed the label Needs rebase on Sep 28, 2020

hebasto force-pushed on Sep 29, 2020

hebasto commented at 10:10 AM on September 29, 2020: member

Rebased 3a310fbf1733e2ddaf1e6707251c409b287838de -> 8e6c42797e0c5b30df34f464eb3b1cddc477da26 (pr19393.03 -> pr19393.05) due to the conflict with #19804.

NelsonGaldeman commented at 7:18 AM on February 8, 2021: contributor

Concept ACK

I support the increased coverage proposed by this PR
I agree with jonatack it would be better to test against the actual changes instead of debug log output. Although, I understand the data needed to do such change is not currently available.
I've compiled 6c61408 commit version and ran the p2p_invalid_tx tests against it, they all passed successfully.
The code and styling looks ok for me

leonardojobim approved

leonardojobim commented at 7:05 PM on February 19, 2021: none

Concept ACK. It expands the test cases that cause the removal of the orphan transactions.

I also agree it would be better to test against the actual changes, but as far I know there's no way in these tests to access the orphan pool maintained in the mapOrphanTransactionsdata structure to perform this validation.

I ran successfully this test on Ubuntu 20.04.

aarmoa approved

aarmoa commented at 2:53 AM on March 1, 2021: none

Approach ACK. To validate the new verification work as expected I did the following temporary change while running the test locally: Line 168:

If assertion is done for 99 number of orphans instead of 100, test fails.
If assertion is done for node 23 instead of 24, test fails.

Line 190:

Added a node.assert_debug_log() with the message "Erased 1 orphan tx included or conflicted by block" as unexpected, to ensure it is logged only when block_A is sent. The test runs without failures.

Line 219:

Added a node.assert_debug_log() with the message "Erased 1 orphan tx included or conflicted by block" as unexpected, to ensure it is logged only when block_B is sent. The test runs without failures.

Tested in Linux Mint 20 64 bits.

practicalswift commented at 7:49 PM on June 23, 2021: contributor

Concept ACK

in test/functional/p2p_invalid_tx.py:95 in 8e6c42797e outdated

  91 | @@ -93,24 +92,24 @@ def run_test(self):
  92 |          SCRIPT_PUB_KEY_OP_TRUE = b'\x51\x75' * 15 + b'\x51'
  93 |          tx_withhold = CTransaction()
  94 |          tx_withhold.vin.append(CTxIn(outpoint=COutPoint(block1.vtx[0].sha256, 0)))
  95 | -        tx_withhold.vout.append(CTxOut(nValue=50 * COIN - 12000, scriptPubKey=SCRIPT_PUB_KEY_OP_TRUE))
  96 | +        tx_withhold.vout = [CTxOut(nValue=25 * COIN - 12000, scriptPubKey=SCRIPT_PUB_KEY_OP_TRUE)] * 2

ShubhamPalriwala commented at 8:43 PM on July 27, 2021:

nit: Having append() here would maintain consistency across the entire file

hebasto commented at 5:17 AM on September 3, 2021:

See the current code in the master branch https://github.com/bitcoin/bitcoin/blob/dd097c42df7378c9d0114c04c82b3c38c18e13dc/test/functional/p2p_invalid_tx.py#L102

in test/functional/p2p_invalid_tx.py:101 in 8e6c42797e outdated

  98 |  
  99 |          # Our first orphan tx with some outputs to create further orphan txs
 100 |          tx_orphan_1 = CTransaction()
 101 |          tx_orphan_1.vin.append(CTxIn(outpoint=COutPoint(tx_withhold.sha256, 0)))
 102 | -        tx_orphan_1.vout = [CTxOut(nValue=10 * COIN, scriptPubKey=SCRIPT_PUB_KEY_OP_TRUE)] * 3
 103 | +        tx_orphan_1.vout = [CTxOut(nValue=8 * COIN, scriptPubKey=SCRIPT_PUB_KEY_OP_TRUE)] * 3

ShubhamPalriwala commented at 8:43 PM on July 27, 2021:

nit: Having append() here would maintain consistency across the entire file

hebasto commented at 5:17 AM on September 3, 2021:

See the current code in the master branch https://github.com/bitcoin/bitcoin/blob/dd097c42df7378c9d0114c04c82b3c38c18e13dc/test/functional/p2p_invalid_tx.py#L102

in test/functional/p2p_invalid_tx.py:174 in 8e6c42797e outdated

 169 | +            self.reconnect_p2p(num_connections=1)
 170 | +
 171 | +        self.log.info('Test that a transaction in the orphan pool is included in a new tip block causes erase this transaction from the orphan pool')
 172 | +        tx_withhold_until_block_A = CTransaction()
 173 | +        tx_withhold_until_block_A.vin.append(CTxIn(outpoint=COutPoint(tx_withhold.sha256, 1)))
 174 | +        tx_withhold_until_block_A.vout = [CTxOut(nValue=12 * COIN, scriptPubKey=SCRIPT_PUB_KEY_OP_TRUE)] * 2

ShubhamPalriwala commented at 8:43 PM on July 27, 2021:

nit: Having append() here would maintain consistency across the entire file

hebasto commented at 5:17 AM on September 3, 2021:

See the current code in the master branch https://github.com/bitcoin/bitcoin/blob/dd097c42df7378c9d0114c04c82b3c38c18e13dc/test/functional/p2p_invalid_tx.py#L102

ShubhamPalriwala commented at 8:52 PM on July 27, 2021: contributor

tACK 73278e3fda86f89ae70b8922f029e6b2d72d6bd6!

Suggestion: the log.info() messages across the PR can be framed in a more clear and concise way.

I completely agree with @leonardojobim here!

Concept ACK. It expands the test cases that cause the removal of the orphan transactions.

I also agree it would be better to test against the actual changes, but as far I know there's no way in these tests to access the orphan pool maintained in the mapOrphanTransactionsdata structure to perform this validation.

I ran successfully this test on Ubuntu 20.04.

Tested on Ubuntu 21.04 works fine

aitorjs commented at 6:12 PM on August 25, 2021: contributor

I read all the test and I found sense to it, ACK.
Compiles well in Ubuntu 20.04.
I liked the increased coverage proposed by this PR. :)

MarcoFalke commented at 8:10 AM on August 26, 2021: member

Needs rebase.

Tests don't pass for me on the first commit.

AssertionError: [node 0] Expected messages "['Erased 100 orphan tx from peer=24']" does not partially match log:

 - 2021-08-26T08:09:23.355383Z [http] [httpserver.cpp:237] [http_request_cb] Received a POST request for / from 127.0.0.1:41922
 - 2021-08-26T08:09:23.355461Z [httpworker.3] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getpeerinfo user=__cookie__
 - 2021-08-26T08:09:23.355648Z [net] [net.cpp:1599] [SocketHandler] socket closed for peer=25
 - 2021-08-26T08:09:23.355659Z [net] [net.cpp:506] [CloseSocketDisconnect] disconnecting peer=25
 - 2021-08-26T08:09:23.355870Z [net] [txorphanage.cpp:102] [EraseForPeer] Erased 100 orphan tx from peer=25

MarcoFalke commented at 8:14 AM on August 30, 2021: member

Tests don't pass for me on the first commit.

After a rebase, that is.

test: Add test for erase orphan tx from peer 5c049780c8

test: Add test for erase orphan tx included by block fa45bb2119

test: Add test for erase orphan tx conflicted by block c0a5fceee9

hebasto force-pushed on Sep 3, 2021

hebasto commented at 5:15 AM on September 3, 2021: member

Needs rebase.

Tests don't pass for me on the first commit.

Rebased 8e6c42797e0c5b30df34f464eb3b1cddc477da26 -> c0a5fceee9858afd24fe0bf655b7b30728e96e78 (pr19393.05 -> pr19393.06).

in test/functional/p2p_invalid_tx.py:168 in c0a5fceee9

 163 |          rejected_parent.rehash()
 164 |          with node.assert_debug_log(['not keeping orphan with rejected parents {}'.format(rejected_parent.hash)]):
 165 |              node.p2ps[0].send_txs_and_test([rejected_parent], node, success=False)
 166 |  
 167 | +        self.log.info('Test that a peer disconnection causes erase its transactions from the orphan pool')
 168 | +        with node.assert_debug_log(['Erased 100 orphan tx from peer=25']):

pg156 commented at 2:38 AM on December 19, 2021:

Let me know if this kind of suggestions is not what you are looking for in terms of reviews at this stage? Feel free to ignore.

How about this to remove the magic number 25 to possibly make it a bit more readable and robust (to me)?

peer_node_id = node.getpeerinfo()[0]['id']
with node.assert_debug_log([f'Erased 100 orphan tx from peer={peer_node_id}']):
    self.reconnect_p2p(num_connections=1)

And the number 100 is the default max orphan pool size -maxorphantx, which may also be changed to a readable variable (if necessary) by something like this (untested). Also it is safer in case of default size change.

def set_test_params(self):
    max_orphan_tx = 100
    self.extra_args = [[f'-maxorphantx={max_orphan_tx}']]

Then use max_orphan_tx in place of 100.

kouloumos commented at 2:36 PM on June 16, 2022:

For the 2 suggested changes of this comment:

I agree with the magic number change as the peer_node_id will change on potential future structural changes of this test. Saying that, I believe that potential confusion my the number 25 is more of an issue (although minor). Another solution could be

        with node.assert_debug_log(['Erased 100 orphan tx from peer']):

If the default size change, this will test non-default behavior & it will still need a change. However, I agree that the addition of a DEFAULT_MAX_ORPHAN_TRANSACTIONS (similar to other tests) with additional usage on L151 could increase readability.

in test/functional/p2p_invalid_tx.py:188 in c0a5fceee9

 183 | +        node.p2ps[0].send_txs_and_test([tx_orphan_include_by_block_A], node, success=False)
 184 | +
 185 | +        tip = int(node.getbestblockhash(), 16)
 186 | +        height = node.getblockcount() + 1
 187 | +        block_A = create_block(tip, create_coinbase(height))
 188 | +        block_A.vtx.extend([tx_withhold, tx_withhold_until_block_A, tx_orphan_include_by_block_A])

pg156 commented at 2:51 AM on December 19, 2021:

Please let me know if any of this is incorrect, thanks.

For the test, there are 3 transactions: parent -> child -> grand child, the peer only sends grand child to node, and then sends a block of (parent, child, grand child) to node, resulting in removing of grand child in the orphan pool.

If the block has only (child, grand child) instead, the test fails as expected, because grand child is still considered an orphan.

block_A.vtx.extend([tx_withhold_until_block_A, tx_orphan_include_by_block_A])

But I don't understand why sending a block of (parent, child) also fails the test? As grand child now receives child and parent in the new block, it can be verified and removed from orphan pool?

block_A.vtx.extend([tx_withhold, tx_withhold_until_block_A])

kouloumos commented at 3:26 PM on June 17, 2022:

When the grandchild was added it was missing inputs thus added to the orphan pool, but those orphans are not reevaluated at each newly connected block.

Taking a look into the codebase, when a new orphan tx is added, there are a few indexes to the OrhanMap, one of them is from the parents' COutPoint to the tx. On a newly connected block, that index is used to check if the included transaction's parents have connection to any other txns from the orphan pool, and those are evicted.

So in you example, when child (tx_withhold_until_block_A) is evaluated, eviction looks for txns in the pool also connected to the parent (tx_withhold) and not grandchildren (tx_orphan_include_by_block_A) connected to the child.

pg156 commented at 3:05 AM on December 19, 2021: none

Reviewed to https://github.com/bitcoin/bitcoin/pull/19393/commits/c0a5fceee9858afd24fe0bf655b7b30728e96e78. Concept ACK. Agree due to the lack of RPC calls to inspect orphan pool, using assert_debug_log to match strings in log is a reasonable way to test.

Tested successfully by running make check and test/functional/test_runner.py.

If I understand correctly, https://github.com/bitcoin/bitcoin/pull/19393/commits/5c049780c8b310428cf72fb304bf0c1071742785 tests 100 orphan transactions sent by a peer to the node are removed after the peer is disconnected. (The peer initially sent 101 orphan transactions to the node. 1 orphan tx is removed because the default max orphan pool size -maxorphantx is 100.) This makes sense.

In https://github.com/bitcoin/bitcoin/commit/c0a5fceee9858afd24fe0bf655b7b30728e96e78, an orphan transaction is sent first to node, then a block with a conflicting transaction is sent to node, resulting in removing the orphan transaction. This is also reasonable.

Questions and suggestions are in below.

aureleoules commented at 12:42 PM on March 10, 2022: member

tACK c0a5fceee9858afd24fe0bf655b7b30728e96e78 (make check and test/functional/test_runner.py). Tested on NixOS 22.05 64 bits.

I carefully read and understood the functions being tested:
https://github.com/bitcoin/bitcoin/blob/c0a5fceee9858afd24fe0bf655b7b30728e96e78/src/txorphanage.cpp#L88-L103 https://github.com/bitcoin/bitcoin/blob/c0a5fceee9858afd24fe0bf655b7b30728e96e78/src/txorphanage.cpp#L56-L86

I commented out locally src/txorphanage.cpp:189 and the tests fail accordingly.
Added tests seem to correctly test the behavior.

nit: I would agree with pg156, magic numbers should be changed to variables for increased readability and better comprehension.

nit: I found it a bit confusing the use of *_A and *_B variables as I first thought the two tests were sequentially dependent. Would it make more sense to use unique variables that would get overridden by the second test, or separate both tests in different methods completely? I hope this is not too nitty but it was my initial thought.

kouloumos commented at 3:43 PM on June 17, 2022: member

ACK c0a5fceee9858afd24fe0bf655b7b30728e96e78 with a nit per #19393 (review).

The description of the flow in #19393 (review) might be useful for reviewers to understand the behavior tested on fa45bb21193ae0c220cfc224d5e3ea0e7f3ec988 & c0a5fceee9858afd24fe0bf655b7b30728e96e78.

MarcoFalke merged this on Jul 5, 2022

MarcoFalke closed this on Jul 5, 2022

sidhujag referenced this in commit e7ec460ba0 on Jul 5, 2022

hebasto deleted the branch on Jul 5, 2022

DrahtBot locked this on Jul 5, 2023