zmq test: fix sync-up by matching notification to generated block

theStack commented at 6:45 pm on February 27, 2021: member

This is a follow-up PR for #21008, fixes #21216.

In the course of investigating the problem with jnewbery (analyzing the Cirrus log https://cirrus-ci.com/task/4660108304056320), it turned out that the “sync up” procedure of repeatedly generating a block and waiting for a notification with timeout is too brittle in its current form, as the following scenario could happen:

generate block A
receive notification, timeout happens => repeat procedure
generate block B
node publishes block A notification
receive notification, we receive the one caused by block A (!!!) => sync-up procedure is completed
node publishes block B notification
the actual test starts
on the first notification reception, the one caused by block B is received, rather than the one actually caused by test code => assertion failure

This change in the PR ensures that after each test block generation, we wait for the notification that is actually caused by that block and ignore others from possibly earlier blocks. The matching is kind of ugly, it assumes that one out of four components in the block is contained in the notification: the block hash, the tx id, the raw block data or the raw transaction data. (Unfortunately we have to support all publisher topics.)

I’m aware that this is quite a lot of code now only for establishing a robust test setup. OTOH I wouldn’t know of a better method right now, suggestions are very welcome.

Note for potential reviewers: for both reproducing the issue on master branch and verifying on PR branch, one can simply generate two blocks in the sync-up procedure rather than one.

DrahtBot added the label Tests on Feb 27, 2021

theStack force-pushed on Feb 27, 2021

jonatack commented at 8:33 pm on February 27, 2021: member

Approach ACK, thanks for working on this.

 0-# Helper class for setting up a ZMQ test via the "sync up" procedure.
 1-# Generates a block on the specified node on instantiation and provides a method to check
 2-# whether a ZMQ notification matches, i.e. the event was caused by this generated block.
 3-# Assumes that a notification either contains the generated block's hash, it's
 4-# (coinbase) transaction id, the raw block or raw transaction data.
 5 class ZMQTestSetupBlock:
 6+    """Helper class for setting up a ZMQ test via the "sync up" procedure.
 7+    Generates a block on the specified node on instantiation and provides a
 8+    method to check whether a ZMQ notification matches, i.e. the event was
 9+    caused by this generated block. Assumes that a notification either contains
10+    the generated block's hash, it's (coinbase) transaction id, the raw block or
11+    raw transaction data.
12+    """
13+
14     def __init__(self, node):
15         self.block_hash = node.generate(1)[0]
16         coinbase = node.getblock(self.block_hash, 2)['tx'][0]
17@@ -76,10 +79,12 @@ class ZMQTestSetupBlock:
18         self.raw_block = node.getblock(self.block_hash, 0)
19 
20     def caused_notification(self, notification):
21-        return self.block_hash in notification or \
22-               self.tx_hash in notification or \
23-               self.raw_block in notification or \
24-               self.raw_tx in notification
25+        return (
26+            self.block_hash in notification
27+            or self.tx_hash in notification
28+            or self.raw_block in notification
29+            or self.raw_tx in notification
30+        )
31 
32 
33 class ZMQTest (BitcoinTestFramework):
34@@ -136,7 +141,7 @@ class ZMQTest (BitcoinTestFramework):
35             for sub in subscribers:
36                 try:
37                     while not test_block.caused_notification(sub.receive().hex()):
38-                        self.log.debug("Ignoring sync-up notification for previoulsy generated block.")
39+                        self.log.debug("Ignoring sync-up notification for previously generated block.")
40                 except zmq.error.Again:
41                     self.log.debug("Didn't receive sync-up notification, trying again.")
42                     recv_failed = True
43@@ -361,7 +366,7 @@ class ZMQTest (BitcoinTestFramework):
44             block_count = self.nodes[0].getblockcount()
45             best_hash = self.nodes[0].getbestblockhash()
46             self.nodes[0].invalidateblock(best_hash)
47-            sleep(2) # Bit of room to make sure transaction things happened
48+            sleep(2)  # Bit of room to make sure transaction things happened
49 
50             # Make sure getrawmempool mempool_sequence results aren't "queued" but immediately reflective
51             # of the time they were gathered.
52@@ -410,8 +415,8 @@ class ZMQTest (BitcoinTestFramework):
53             assert_equal(label, "A")
54             # More transactions to be simply mined
55             for i in range(len(more_tx)):
56-                    assert_equal((more_tx[i], "A", mempool_seq), seq.receive_sequence())
57-                    mempool_seq += 1
58+                assert_equal((more_tx[i], "A", mempool_seq), seq.receive_sequence())
59+                mempool_seq += 1
60             # Bumped by rbf
61             assert_equal((orig_txid, "R", mempool_seq), seq.receive_sequence())
62             mempool_seq += 1
63@@ -426,7 +431,7 @@ class ZMQTest (BitcoinTestFramework):
64             assert_equal((orig_txid_2, "A", mempool_seq), seq.receive_sequence())
65             mempool_seq += 1
66             self.nodes[0].generatetoaddress(1, ADDRESS_BCRT1_UNSPENDABLE)
67-            self.sync_all() # want to make sure we didn't break "consensus" for other tests
68+            self.sync_all()  # want to make sure we didn't break "consensus" for other tests
69 
70     def test_mempool_sync(self):

zmq test: fix sync-up by matching notification to generated block

It turned out that the "sync up" procedure of repeatedly generating a
block and waiting for a notification once with timeout is too naive in
its current form, as the following scenario could happen:
    - generate block A
    - receive notification, timeout happens -> repeat procedure
    - generate block B
    - node publishes block A notification
    - receive notification, we receive the one caused by block A
      -> sync-up procedure is completed
    - node publishes block B
    - the actual test starts
    - on the first notification reception, one caused by block B is received,
      rather than the one actually caused by test code, leading to failure

This change ensures that after each test block generation, we wait for
the notification that is actually caused by that block and ignore others
from possibly earlier blocks.

Co-authored-by: Jon Atack <jon@atack.com>

8a8c6383f6

theStack force-pushed on Mar 1, 2021

theStack commented at 0:41 am on March 1, 2021: member

Force-pushed with all changes suggested by @jonatack (thanks for catching the typo and the style fixups, looks much better now! 🚀 ).

MarcoFalke commented at 10:30 am on March 2, 2021: member

Concept ACK 8a8c6383f6f9da10b931f00ca1220408fede8f35

Thanks!

MarcoFalke merged this on Mar 2, 2021

MarcoFalke closed this on Mar 2, 2021

sidhujag referenced this in commit 4214c9c9c6 on Mar 2, 2021

DrahtBot locked this on Aug 16, 2022

zmq test: fix sync-up by matching notification to generated block #21310