test: Add more tests for orphan tx handling #19393

hebasto · 2020-06-27T10:28:25Z

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.

jonatack

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.

test/functional/p2p_invalid_tx.py

jonatack · 2020-06-28T12:49:12Z

test/functional/p2p_invalid_tx.py

        with node.assert_debug_log(['not keeping orphan with rejected parents {}'.format(rejected_parent.hash)]):
            node.p2p.send_txs_and_test([rejected_parent], node, success=False)

+        self.log.info('Test erase of orphan tx from peer')


48b43e2

Suggested change

self.log.info('Test erase of orphan tx from peer')

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

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

jonatack · 2020-06-28T13:03:22Z

test/functional/p2p_invalid_tx.py

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


What is being asserted in this subtest?

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.

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.

test/functional/p2p_invalid_tx.py

jonatack · 2020-06-28T13:18:07Z

test/functional/p2p_invalid_tx.py

            node.p2p.send_txs_and_test([rejected_parent], node, success=False)

+        self.log.info('Test erase of orphan tx from peer')
+        with node.assert_debug_log(['Erased 100 orphan tx from peer=24']):


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

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

hebasto · 2020-06-28T15:34:43Z

@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 · 2020-06-28T17:15:57Z

Updated 10f7f75 -> a95a6d9 (pr19393.01 -> pr19393.02, diff):

addressed @jonatack's comments

hebasto · 2020-06-28T18:16:48Z

Updated a95a6d9 -> 3a310fb (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 · 2020-08-26T04:07:18Z

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

Conflicts

No conflicts as of last run.

hebasto · 2020-09-29T10:10:55Z

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

NelsonGaldeman · 2021-02-08T07:18:29Z

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

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

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 · 2021-06-23T19:49:59Z

Concept ACK

ShubhamPalriwala

tACK 73278e3!

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

ShubhamPalriwala · 2021-07-27T20:43:18Z

test/functional/p2p_invalid_tx.py

        tx_withhold = CTransaction()
        tx_withhold.vin.append(CTxIn(outpoint=COutPoint(block1.vtx[0].sha256, 0)))
-        tx_withhold.vout.append(CTxOut(nValue=50 * COIN - 12000, scriptPubKey=SCRIPT_PUB_KEY_OP_TRUE))
+        tx_withhold.vout = [CTxOut(nValue=25 * COIN - 12000, scriptPubKey=SCRIPT_PUB_KEY_OP_TRUE)] * 2


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

See the current code in the master branch

bitcoin/test/functional/p2p_invalid_tx.py

Line 102 in dd097c4

tx_orphan_1.vout = [CTxOut(nValue=10 * COIN, scriptPubKey=SCRIPT_PUB_KEY_OP_TRUE)] * 3

ShubhamPalriwala · 2021-07-27T20:43:32Z

test/functional/p2p_invalid_tx.py

        tx_orphan_1 = CTransaction()
        tx_orphan_1.vin.append(CTxIn(outpoint=COutPoint(tx_withhold.sha256, 0)))
-        tx_orphan_1.vout = [CTxOut(nValue=10 * COIN, scriptPubKey=SCRIPT_PUB_KEY_OP_TRUE)] * 3
+        tx_orphan_1.vout = [CTxOut(nValue=8 * COIN, scriptPubKey=SCRIPT_PUB_KEY_OP_TRUE)] * 3


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

See the current code in the master branch

bitcoin/test/functional/p2p_invalid_tx.py

Line 102 in dd097c4

tx_orphan_1.vout = [CTxOut(nValue=10 * COIN, scriptPubKey=SCRIPT_PUB_KEY_OP_TRUE)] * 3

ShubhamPalriwala · 2021-07-27T20:43:43Z

test/functional/p2p_invalid_tx.py

+        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')
+        tx_withhold_until_block_A = CTransaction()
+        tx_withhold_until_block_A.vin.append(CTxIn(outpoint=COutPoint(tx_withhold.sha256, 1)))
+        tx_withhold_until_block_A.vout = [CTxOut(nValue=12 * COIN, scriptPubKey=SCRIPT_PUB_KEY_OP_TRUE)] * 2


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

See the current code in the master branch

bitcoin/test/functional/p2p_invalid_tx.py

Line 102 in dd097c4

tx_orphan_1.vout = [CTxOut(nValue=10 * COIN, scriptPubKey=SCRIPT_PUB_KEY_OP_TRUE)] * 3

aitorjs · 2021-08-25T18:12:20Z

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

maflcko · 2021-08-26T08:10:21Z

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

maflcko · 2021-08-30T08:14:29Z

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

After a rebase, that is.

hebasto · 2021-09-03T05:15:21Z

Needs rebase.

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

Rebased 8e6c427 -> c0a5fce (pr19393.05 -> pr19393.06).

pg156

Reviewed to c0a5fce. 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, 5c04978 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 c0a5fce, 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.

pg156 · 2021-12-19T02:38:23Z

test/functional/p2p_invalid_tx.py

            node.p2ps[0].send_txs_and_test([rejected_parent], node, success=False)

+        self.log.info('Test that a peer disconnection causes erase its transactions from the orphan pool')
+        with node.assert_debug_log(['Erased 100 orphan tx from peer=25']):


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.

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

Suggested change

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

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.

pg156 · 2021-12-19T02:51:47Z

test/functional/p2p_invalid_tx.py

+        tip = int(node.getbestblockhash(), 16)
+        height = node.getblockcount() + 1
+        block_A = create_block(tip, create_coinbase(height))
+        block_A.vtx.extend([tx_withhold, tx_withhold_until_block_A, tx_orphan_include_by_block_A])


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

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.

aureleoules · 2022-03-10T12:42:49Z

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

I carefully read and understood the functions being tested:

bitcoin/src/txorphanage.cpp

Lines 88 to 103 in c0a5fce

    
           void TxOrphanage::EraseForPeer(NodeId peer) 
        
           { 
        
               AssertLockHeld(g_cs_orphans); 
        
               int nErased = 0; 
        
               std::map<uint256, OrphanTx>::iterator iter = m_orphans.begin(); 
        
               while (iter != m_orphans.end()) 
        
               { 
        
                   std::map<uint256, OrphanTx>::iterator maybeErase = iter++; // increment to avoid iterator becoming invalid 
        
                   if (maybeErase->second.fromPeer == peer) 
        
                   { 
        
                       nErased += EraseTx(maybeErase->second.tx->GetHash()); 
        
                   } 
        
               } 
        
               if (nErased > 0) LogPrint(BCLog::MEMPOOL, "Erased %d orphan tx from peer=%d\n", nErased, peer); 
        
           }

bitcoin/src/txorphanage.cpp

Lines 56 to 86 in c0a5fce

    
           int TxOrphanage::EraseTx(const uint256& txid) 
        
           { 
        
               AssertLockHeld(g_cs_orphans); 
        
               std::map<uint256, OrphanTx>::iterator it = m_orphans.find(txid); 
        
               if (it == m_orphans.end()) 
        
                   return 0; 
        
               for (const CTxIn& txin : it->second.tx->vin) 
        
               { 
        
                   auto itPrev = m_outpoint_to_orphan_it.find(txin.prevout); 
        
                   if (itPrev == m_outpoint_to_orphan_it.end()) 
        
                       continue; 
        
                   itPrev->second.erase(it); 
        
                   if (itPrev->second.empty()) 
        
                       m_outpoint_to_orphan_it.erase(itPrev); 
        
               } 
        
               size_t old_pos = it->second.list_pos; 
        
               assert(m_orphan_list[old_pos] == it); 
        
               if (old_pos + 1 != m_orphan_list.size()) { 
        
                   // Unless we're deleting the last entry in m_orphan_list, move the last 
        
                   // entry to the position we're deleting. 
        
                   auto it_last = m_orphan_list.back(); 
        
                   m_orphan_list[old_pos] = it_last; 
        
                   it_last->second.list_pos = old_pos; 
        
               } 
        
               m_orphan_list.pop_back(); 
        
               m_wtxid_to_orphan_it.erase(it->second.tx->GetWitnessHash()); 
        
               m_orphans.erase(it); 
        
               return 1; 
        
           }

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 · 2022-06-17T15:43:36Z

ACK c0a5fce with a nit per #19393 (comment).

The description of the flow in #19393 (comment) might be useful for reviewers to understand the behavior tested on fa45bb2 & c0a5fce.

c0a5fce test: Add test for erase orphan tx conflicted by block (Hennadii Stepanov) fa45bb2 test: Add test for erase orphan tx included by block (Hennadii Stepanov) 5c04978 test: Add test for erase orphan tx from peer (Hennadii Stepanov) Pull request description: 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 bitcoin#19374. ACKs for top commit: aureleoules: tACK c0a5fce (`make check` and `test/functional/test_runner.py`). kouloumos: ACK c0a5fce with a nit per bitcoin#19393 (comment). pg156: Reviewed to bitcoin@c0a5fce. 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. Tree-SHA512: 98f8deeee2d1c588c7e28a82e513d4a18655084198369db33fe2710458251eeaffed030626940072d7576f57fcbf7d856d761990129e2ca9e372d2ccbd86d07d

fanquake added the Tests label Jun 27, 2020

jonatack reviewed Jun 28, 2020

View reviewed changes

hebasto force-pushed the 200627-test-orphan branch from 10f7f75 to a95a6d9 Compare June 28, 2020 17:12

hebasto force-pushed the 200627-test-orphan branch from a95a6d9 to 3a310fb Compare June 28, 2020 18:14

DrahtBot mentioned this pull request Aug 26, 2020

test/refactor: reference p2p objects explicitly and remove confusing Test_Node.p2p property #19804

Merged

DrahtBot added the Needs rebase label Sep 25, 2020

hebasto force-pushed the 200627-test-orphan branch from 3a310fb to 9979e8b Compare September 28, 2020 17:14

DrahtBot removed the Needs rebase label Sep 28, 2020

hebasto force-pushed the 200627-test-orphan branch from 9979e8b to 8e6c427 Compare September 29, 2020 08:57

leonardojobim approved these changes Feb 19, 2021

View reviewed changes

aarmoa approved these changes Mar 1, 2021

View reviewed changes

ShubhamPalriwala reviewed Jul 27, 2021

View reviewed changes

hebasto added 3 commits September 3, 2021 07:53

test: Add test for erase orphan tx from peer

5c04978

test: Add test for erase orphan tx included by block

fa45bb2

test: Add test for erase orphan tx conflicted by block

c0a5fce

hebasto force-pushed the 200627-test-orphan branch from 8e6c427 to c0a5fce Compare September 3, 2021 05:12

pg156 reviewed Dec 19, 2021

View reviewed changes

maflcko merged commit 195e07f into bitcoin:master Jul 5, 2022

hebasto deleted the 200627-test-orphan branch July 5, 2022 23:56

bitcoin locked and limited conversation to collaborators Jul 5, 2023

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

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

test: Add more tests for orphan tx handling #19393

test: Add more tests for orphan tx handling #19393

Uh oh!

Conversation

hebasto commented Jun 27, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jonatack left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jonatack Jun 28, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

jonatack Jun 28, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

hebasto commented Jun 28, 2020

Uh oh!

hebasto commented Jun 28, 2020

Uh oh!

hebasto commented Jun 28, 2020

Uh oh!

DrahtBot commented Aug 26, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Conflicts

Uh oh!

hebasto commented Sep 29, 2020

Uh oh!

NelsonGaldeman commented Feb 8, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

leonardojobim left a comment

Choose a reason for hiding this comment

Uh oh!

aarmoa left a comment

Choose a reason for hiding this comment

Uh oh!

practicalswift commented Jun 23, 2021

Uh oh!

ShubhamPalriwala left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

aitorjs commented Aug 25, 2021

Uh oh!

maflcko commented Aug 26, 2021

Uh oh!

maflcko commented Aug 30, 2021

Uh oh!

hebasto commented Jun 27, 2020 •

edited

Loading

jonatack left a comment •

edited

Loading

jonatack Jun 28, 2020 •

edited

Loading

jonatack Jun 28, 2020 •

edited

Loading

DrahtBot commented Aug 26, 2020 •

edited

Loading

NelsonGaldeman commented Feb 8, 2021 •

edited

Loading

pg156 left a comment •

edited

Loading

aureleoules commented Mar 10, 2022 •

edited

Loading