Merge bitcoin#27944: test: various USDT functional test cleanups (278…

…31 follow-ups)

9f55773 test: refactor: usdt_mempool: store all events (stickies-v)
bc43270 test: refactor: remove unnecessary nonlocal (stickies-v)
326db63 test: log sanity check assertion failures (stickies-v)
f5525ad test: store utxocache events (stickies-v)
f1b99ac test: refactor: deduplicate handle_utxocache_* logic (stickies-v)
ad90ba3 test: refactor:  rename inbound to is_inbound (stickies-v)
afc0224 test: refactor: remove unnecessary blocks_checked counter (stickies-v)

Pull request description:

  Various cleanups to the USDT functional tests, largely (but not exclusively) follow-ups to bitcoin#27831 (review). Except for slightly different logging behaviour in "test: store utxocache events" and "test: log sanity check assertion failures", this is a refactor PR, removing unnecessary code and (imo) making it more readable and maintainable.

  The rationale for each change is in the corresponding commit message.

  Note: except for "test: store utxocache events" (which relies on its parent, and I separated into two commits because we may want the parent but not the child), all commits are stand-alone and I'm okay with dropping one/multiple commits if they turn out to be controversial or undesired.

ACKs for top commit:
  0xB10C:
    ACK 9f55773. Reviewed the code and ran the USDT interface tests. I stepped through the commits and think all changes are reasonable.

Tree-SHA512: 6c37a0265b6c26d4f9552a056a690b8f86f7304bd33b4419febd8b17369cf6af799cb87c16df35d0c2a1b839ad31de24661d4384eafa88816c2051c522fd3bf5

test/functional/interface_usdt_mempool.py

@@ -137,9 +137,7 @@ def added_test(self):
         """Add a transaction to the mempool and make sure the tracepoint returns
         the expected txid, vsize, and fee."""
 
-        EXPECTED_ADDED_EVENTS = 1
-        handled_added_events = 0
-        event = None
+        events = []
 
         self.log.info("Hooking into mempool:added tracepoint...")
         node = self.nodes[0]
@@ -148,9 +146,7 @@ def added_test(self):
         bpf = BPF(text=MEMPOOL_TRACEPOINTS_PROGRAM, usdt_contexts=[ctx], debug=0)
 
         def handle_added_event(_, data, __):
-            nonlocal event, handled_added_events
-            event = bpf["added_events"].event(data)
-            handled_added_events += 1
+            events.append(bpf["added_events"].event(data))
 
         bpf["added_events"].open_perf_buffer(handle_added_event)
 
@@ -165,7 +161,8 @@ def handle_added_event(_, data, __):
         self.generate(node, 1)
 
         self.log.info("Ensuring mempool:added event was handled successfully...")
-        assert_equal(EXPECTED_ADDED_EVENTS, handled_added_events)
+        assert_equal(1, len(events))
+        event = events[0]
         assert_equal(bytes(event.hash)[::-1].hex(), tx["txid"])
         assert_equal(event.vsize, tx["tx"].get_vsize())
         assert_equal(event.fee, fee)
@@ -177,9 +174,7 @@ def removed_test(self):
         """Expire a transaction from the mempool and make sure the tracepoint returns
         the expected txid, expiry reason, vsize, and fee."""
 
-        EXPECTED_REMOVED_EVENTS = 1
-        handled_removed_events = 0
-        event = None
+        events = []
 
         self.log.info("Hooking into mempool:removed tracepoint...")
         node = self.nodes[0]
@@ -188,9 +183,7 @@ def removed_test(self):
         bpf = BPF(text=MEMPOOL_TRACEPOINTS_PROGRAM, usdt_contexts=[ctx], debug=0)
 
         def handle_removed_event(_, data, __):
-            nonlocal event, handled_removed_events
-            event = bpf["removed_events"].event(data)
-            handled_removed_events += 1
+            events.append(bpf["removed_events"].event(data))
 
         bpf["removed_events"].open_perf_buffer(handle_removed_event)
 
@@ -212,7 +205,8 @@ def handle_removed_event(_, data, __):
         bpf.perf_buffer_poll(timeout=200)
 
         self.log.info("Ensuring mempool:removed event was handled successfully...")
-        assert_equal(EXPECTED_REMOVED_EVENTS, handled_removed_events)
+        assert_equal(1, len(events))
+        event = events[0]
         assert_equal(bytes(event.hash)[::-1].hex(), txid)
         assert_equal(event.reason.decode("UTF-8"), "expiry")
         assert_equal(event.vsize, tx["tx"].get_vsize())
@@ -226,9 +220,7 @@ def replaced_test(self):
         """Replace one and two transactions in the mempool and make sure the tracepoint
         returns the expected txids, vsizes, and fees."""
 
-        EXPECTED_REPLACED_EVENTS = 1
-        handled_replaced_events = 0
-        event = None
+        events = []
 
         self.log.info("Hooking into mempool:replaced tracepoint...")
         node = self.nodes[0]
@@ -237,9 +229,7 @@ def replaced_test(self):
         bpf = BPF(text=MEMPOOL_TRACEPOINTS_PROGRAM, usdt_contexts=[ctx], debug=0)
 
         def handle_replaced_event(_, data, __):
-            nonlocal event, handled_replaced_events
-            event = bpf["replaced_events"].event(data)
-            handled_replaced_events += 1
+            events.append(bpf["replaced_events"].event(data))
 
         bpf["replaced_events"].open_perf_buffer(handle_replaced_event)
 
@@ -261,7 +251,8 @@ def handle_replaced_event(_, data, __):
         bpf.perf_buffer_poll(timeout=200)
 
         self.log.info("Ensuring mempool:replaced event was handled successfully...")
-        assert_equal(EXPECTED_REPLACED_EVENTS, handled_replaced_events)
+        assert_equal(1, len(events))
+        event = events[0]
         assert_equal(bytes(event.replaced_hash)[::-1].hex(), original_tx["txid"])
         assert_equal(event.replaced_vsize, original_tx["tx"].get_vsize())
         assert_equal(event.replaced_fee, original_fee)
@@ -277,9 +268,7 @@ def rejected_test(self):
         """Create an invalid transaction and make sure the tracepoint returns
         the expected txid, rejection reason, peer id, and peer address."""
 
-        EXPECTED_REJECTED_EVENTS = 1
-        handled_rejected_events = 0
-        event = None
+        events = []
 
         self.log.info("Adding P2P connection...")
         node = self.nodes[0]
@@ -291,9 +280,7 @@ def rejected_test(self):
         bpf = BPF(text=MEMPOOL_TRACEPOINTS_PROGRAM, usdt_contexts=[ctx], debug=0)
 
         def handle_rejected_event(_, data, __):
-            nonlocal event, handled_rejected_events
-            event = bpf["rejected_events"].event(data)
-            handled_rejected_events += 1
+            events.append(bpf["rejected_events"].event(data))
 
         bpf["rejected_events"].open_perf_buffer(handle_rejected_event)
 
@@ -305,7 +292,8 @@ def handle_rejected_event(_, data, __):
         bpf.perf_buffer_poll(timeout=200)
 
         self.log.info("Ensuring mempool:rejected event was handled successfully...")
-        assert_equal(EXPECTED_REJECTED_EVENTS, handled_rejected_events)
+        assert_equal(1, len(events))
+        event = events[0]
         assert_equal(bytes(event.hash)[::-1].hex(), tx["tx"].hash)
         # The next test is already known to fail, so disable it to avoid
         # wasting CPU time and developer time. See

test/functional/interface_usdt_net.py

@@ -121,25 +121,24 @@ def __repr__(self):
         checked_outbound_version_msg = 0
         events = []
 
-        def check_p2p_message(event, inbound):
+        def check_p2p_message(event, is_inbound):
             nonlocal checked_inbound_version_msg, checked_outbound_version_msg
             if event.msg_type.decode("utf-8") == "version":
                 self.log.info(
-                    f"check_p2p_message(): {'inbound' if inbound else 'outbound'} {event}")
+                    f"check_p2p_message(): {'inbound' if is_inbound else 'outbound'} {event}")
                 peer = self.nodes[0].getpeerinfo()[0]
                 msg = msg_version()
                 msg.deserialize(BytesIO(bytes(event.msg[:event.msg_size])))
                 assert_equal(peer["id"], event.peer_id, peer["id"])
                 assert_equal(peer["addr"], event.peer_addr.decode("utf-8"))
                 assert_equal(peer["connection_type"],
                              event.peer_conn_type.decode("utf-8"))
-                if inbound:
+                if is_inbound:
                     checked_inbound_version_msg += 1
                 else:
                     checked_outbound_version_msg += 1
 
         def handle_inbound(_, data, __):
-            nonlocal events
             event = ctypes.cast(data, ctypes.POINTER(P2PMessage)).contents
             events.append((event, True))
 
@@ -157,8 +156,8 @@ def handle_outbound(_, data, __):
 
         self.log.info(
             "check receipt and content of in- and outbound version messages")
-        for event, inbound in events:
-            check_p2p_message(event, inbound)
+        for event, is_inbound in events:
+            check_p2p_message(event, is_inbound)
         assert_equal(EXPECTED_INOUTBOUND_VERSION_MSG,
                      checked_inbound_version_msg)
         assert_equal(EXPECTED_INOUTBOUND_VERSION_MSG,

test/functional/interface_usdt_utxocache.py

@@ -252,43 +252,30 @@ def test_add_spent(self):
         # that the handle_* functions succeeded.
         EXPECTED_HANDLE_ADD_SUCCESS = 2
         EXPECTED_HANDLE_SPENT_SUCCESS = 1
-        handle_add_succeeds = 0
-        handle_spent_succeeds = 0
 
-        expected_utxocache_spents = []
         expected_utxocache_adds = []
+        expected_utxocache_spents = []
+
+        actual_utxocache_adds = []
+        actual_utxocache_spents = []
+
+        def compare_utxo_with_event(utxo, event):
+            """Compare a utxo dict to the event produced by BPF"""
+            assert_equal(utxo["txid"], bytes(event.txid[::-1]).hex())
+            assert_equal(utxo["index"], event.index)
+            assert_equal(utxo["height"], event.height)
+            assert_equal(utxo["value"], event.value)
+            assert_equal(utxo["is_coinbase"], event.is_coinbase)
 
         def handle_utxocache_add(_, data, __):
-            nonlocal handle_add_succeeds
             event = ctypes.cast(data, ctypes.POINTER(UTXOCacheChange)).contents
             self.log.info(f"handle_utxocache_add(): {event}")
-            add = expected_utxocache_adds.pop(0)
-            try:
-                assert_equal(add["txid"], bytes(event.txid[::-1]).hex())
-                assert_equal(add["index"], event.index)
-                assert_equal(add["height"], event.height)
-                assert_equal(add["value"], event.value)
-                assert_equal(add["is_coinbase"], event.is_coinbase)
-            except AssertionError:
-                self.log.exception("Assertion failed")
-            else:
-                handle_add_succeeds += 1
+            actual_utxocache_adds.append(event)
 
         def handle_utxocache_spent(_, data, __):
-            nonlocal handle_spent_succeeds
             event = ctypes.cast(data, ctypes.POINTER(UTXOCacheChange)).contents
             self.log.info(f"handle_utxocache_spent(): {event}")
-            spent = expected_utxocache_spents.pop(0)
-            try:
-                assert_equal(spent["txid"], bytes(event.txid[::-1]).hex())
-                assert_equal(spent["index"], event.index)
-                assert_equal(spent["height"], event.height)
-                assert_equal(spent["value"], event.value)
-                assert_equal(spent["is_coinbase"], event.is_coinbase)
-            except AssertionError:
-                self.log.exception("Assertion failed")
-            else:
-                handle_spent_succeeds += 1
+            actual_utxocache_spents.append(event)
 
         bpf["utxocache_add"].open_perf_buffer(handle_utxocache_add)
         bpf["utxocache_spent"].open_perf_buffer(handle_utxocache_spent)
@@ -324,19 +311,18 @@ def handle_utxocache_spent(_, data, __):
                         "is_coinbase": block_index == 0,
                     })
 
-        assert_equal(EXPECTED_HANDLE_ADD_SUCCESS, len(expected_utxocache_adds))
-        assert_equal(EXPECTED_HANDLE_SPENT_SUCCESS,
-                     len(expected_utxocache_spents))
-
         bpf.perf_buffer_poll(timeout=200)
-        bpf.cleanup()
+
+        assert_equal(EXPECTED_HANDLE_ADD_SUCCESS, len(expected_utxocache_adds), len(actual_utxocache_adds))
+        assert_equal(EXPECTED_HANDLE_SPENT_SUCCESS, len(expected_utxocache_spents), len(actual_utxocache_spents))
 
         self.log.info(
             f"check that we successfully traced {EXPECTED_HANDLE_ADD_SUCCESS} adds and {EXPECTED_HANDLE_SPENT_SUCCESS} spent")
-        assert_equal(0, len(expected_utxocache_adds))
-        assert_equal(0, len(expected_utxocache_spents))
-        assert_equal(EXPECTED_HANDLE_ADD_SUCCESS, handle_add_succeeds)
-        assert_equal(EXPECTED_HANDLE_SPENT_SUCCESS, handle_spent_succeeds)
+        for expected_utxo, actual_event in zip(expected_utxocache_adds + expected_utxocache_spents,
+                                               actual_utxocache_adds + actual_utxocache_spents):
+            compare_utxo_with_event(expected_utxo, actual_event)
+
+        bpf.cleanup()
 
     def test_flush(self):
         """ Tests the utxocache:flush tracepoint API.
@@ -367,9 +353,13 @@ def handle_utxocache_flush(_, data, __):
                 "size": event.size
             })
             # sanity checks only
-            assert event.memory > 0
-            assert event.duration > 0
-            handle_flush_succeeds += 1
+            try:
+                assert event.memory > 0
+                assert event.duration > 0
+            except AssertionError:
+                self.log.exception("Assertion error")
+            else:
+                handle_flush_succeeds += 1
 
         bpf["utxocache_flush"].open_perf_buffer(handle_utxocache_flush)
 

test/functional/interface_usdt_validation.py

@@ -86,7 +86,6 @@ def __repr__(self):
                     self.duration)
 
         BLOCKS_EXPECTED = 2
-        blocks_checked = 0
         expected_blocks = dict()
         events = []
 
@@ -98,11 +97,9 @@ def __repr__(self):
                   usdt_contexts=[ctx], debug=0)
 
         def handle_blockconnected(_, data, __):
-            nonlocal events, blocks_checked
             event = ctypes.cast(data, ctypes.POINTER(Block)).contents
             self.log.info(f"handle_blockconnected(): {event}")
             events.append(event)
-            blocks_checked += 1
 
         bpf["block_connected"].open_perf_buffer(
             handle_blockconnected)
@@ -127,7 +124,7 @@ def handle_blockconnected(_, data, __):
             # only plausibility checks
             assert event.duration > 0
             del expected_blocks[block_hash]
-        assert_equal(BLOCKS_EXPECTED, blocks_checked)
+        assert_equal(BLOCKS_EXPECTED, len(events))
         assert_equal(0, len(expected_blocks))
 
         bpf.cleanup()