Inside Bitcoin

251
252        self.log.info(
253            "hook into the utxocache:add and utxocache:spent tracepoints")
254        ctx = USDT(pid=self.nodes[0].process.pid)
255        ctx.enable_probe(probe="utxocache:add", fn_name="trace_utxocache_add")
256        ctx.enable_probe(probe="utxocache:spent",
257                         fn_name="trace_utxocache_spent")
258        bpf = BPF(text=utxocache_changes_program, usdt_contexts=[ctx], debug=0, cflags=bpf_cflags())
259
260        # The handle_* function is a ctypes callback function called from C. When
261        # we assert in the handle_* function, the AssertError doesn't propagate
262        # back to Python. The exception is ignored. We manually count and assert
263        # that the handle_* functions succeeded.
264        EXPECTED_HANDLE_ADD_SUCCESS = 2
265        EXPECTED_HANDLE_SPENT_SUCCESS = 1
266
267        expected_utxocache_adds = []
268        expected_utxocache_spents = []
269
270        actual_utxocache_adds = []
271        actual_utxocache_spents = []
272
273        def handle_utxocache_add(_, data, __):
274            event = ctypes.cast(data, ctypes.POINTER(UTXOCacheChange)).contents
275            self.log.info(f"handle_utxocache_add(): {event}")
276            actual_utxocache_adds.append(event)
277
278        def handle_utxocache_spent(_, data, __):
279            event = ctypes.cast(data, ctypes.POINTER(UTXOCacheChange)).contents
280            self.log.info(f"handle_utxocache_spent(): {event}")
281            actual_utxocache_spents.append(event)
282
283        bpf["utxocache_add"].open_perf_buffer(handle_utxocache_add)
284        bpf["utxocache_spent"].open_perf_buffer(handle_utxocache_spent)
285
286        # We trigger a block re-connection. This causes changes (add/spent)
287        # to the UTXO-cache which in turn triggers the tracepoints.
288        self.log.info("reconsider the previously invalidated block")
289        self.nodes[0].reconsiderblock(block_hash)
290
291        block = self.nodes[0].getblock(block_hash, 2)
292        for (block_index, tx) in enumerate(block["tx"]):
293            for vin in tx["vin"]:
294                if "coinbase" not in vin:
295                    prevout_tx = self.nodes[0].getrawtransaction(
296                        vin["txid"], True)
297                    prevout_tx_block = self.nodes[0].getblockheader(
298                        prevout_tx["blockhash"])
299                    spends_coinbase = "coinbase" in prevout_tx["vin"][0]
300                    expected_utxocache_spents.append({
301                        "txid": vin["txid"],
302                        "index": vin["vout"],
303                        "height": prevout_tx_block["height"],
304                        "value": int(prevout_tx["vout"][vin["vout"]]["value"] * COIN),
305                        "is_coinbase": spends_coinbase,
306                    })
307            for (i, vout) in enumerate(tx["vout"]):
308                if vout["scriptPubKey"]["type"] != "nulldata":
309                    expected_utxocache_adds.append({
310                        "txid": tx["txid"],
311                        "index": i,
312                        "height": block["height"],
313                        "value": int(vout["value"] * COIN),
314                        "is_coinbase": block_index == 0,
315                    })
316
317        bpf.perf_buffer_poll(timeout=200)
318
319        assert_equal(EXPECTED_HANDLE_ADD_SUCCESS, len(expected_utxocache_adds), len(actual_utxocache_adds))
320        assert_equal(EXPECTED_HANDLE_SPENT_SUCCESS, len(expected_utxocache_spents), len(actual_utxocache_spents))
321
322        self.log.info(
323            f"check that we successfully traced {EXPECTED_HANDLE_ADD_SUCCESS} adds and {EXPECTED_HANDLE_SPENT_SUCCESS} spent")
324
325        # Check that all expected tracepoints are received, but not the order they were received in.
326        # Tracepoint ordering is not strictly guaranteed, so this comparison avoids intermittent failures in the test.
327        def cache_event_to_key(event):
328            return (
329                bytes(event.txid[::-1]).hex(),
330                event.index,
331                event.height,
332                event.value,
333                event.is_coinbase
334            )
335
336        expected_add_keys = {(e["txid"], e["index"], e["height"], e["value"], e["is_coinbase"])
337                             for e in expected_utxocache_adds}
338        expected_spent_keys = {(e["txid"], e["index"], e["height"], e["value"], e["is_coinbase"])
339                              for e in expected_utxocache_spents}
340
341        actual_add_keys = {cache_event_to_key(e) for e in actual_utxocache_adds}
342        actual_spent_keys = {cache_event_to_key(e) for e in actual_utxocache_spents}
343
344        assert_equal(expected_add_keys, actual_add_keys)
345        assert_equal(expected_spent_keys, actual_spent_keys)
346
347        bpf.cleanup()
348
349    def test_flush(self):
350        """ Tests the utxocache:flush tracepoint API.
351            See https://github.com/bitcoin/bitcoin/blob/master/doc/tracing.md#tracepoint-utxocacheflush"""
352
353        self.log.info("test the utxocache:flush tracepoint API")
354        self.log.info("hook into the utxocache:flush tracepoint")
355        ctx = USDT(pid=self.nodes[0].process.pid)
356        ctx.enable_probe(probe="utxocache:flush",
357                         fn_name="trace_utxocache_flush")
358        bpf = BPF(text=utxocache_flushes_program, usdt_contexts=[ctx], debug=0, cflags=bpf_cflags())
359
360        # The handle_* function is a ctypes callback function called from C. When
361        # we assert in the handle_* function, the AssertError doesn't propagate
362        # back to Python. The exception is ignored. We manually count and assert
363        # that the handle_* functions succeeded.
364        EXPECTED_HANDLE_FLUSH_SUCCESS = 3
365        handle_flush_succeeds = 0
366        expected_flushes = list()
367
368        def handle_utxocache_flush(_, data, __):
369            nonlocal handle_flush_succeeds
370            event = ctypes.cast(data, ctypes.POINTER(UTXOCacheFlush)).contents
371            self.log.info(f"handle_utxocache_flush(): {event}")
372            expected_flushes.remove({
373                "mode": FLUSHMODE_NAME[event.mode],
374                "for_prune": event.for_prune,
375                "size": event.size
376            })
377            # sanity checks only
378            try:
379                assert event.memory > 0
380                assert event.duration > 0
381            except AssertionError:
382                self.log.exception("Assertion error")
383            else:
384                handle_flush_succeeds += 1
385
386        bpf["utxocache_flush"].open_perf_buffer(handle_utxocache_flush)
387
388        self.log.info("stop the node to flush the UTXO cache")
389        UTXOS_IN_CACHE = 3 # might need to be changed if the earlier tests are modified
390        # A node shutdown causes two flushes. One that flushes UTXOS_IN_CACHE
391        # UTXOs and one that flushes 0 UTXOs. Normally the 0-UTXO-flush is the
392        # second flush, however it can happen that the order changes.
393        expected_flushes.append({"mode": "FORCE_FLUSH", "for_prune": False, "size": UTXOS_IN_CACHE})
394        expected_flushes.append({"mode": "FORCE_FLUSH", "for_prune": False, "size": 0})
395        self.stop_node(0)
396
397        bpf.perf_buffer_poll(timeout=200)
398        bpf.cleanup()
399
400        self.log.info("check that we don't expect additional flushes")
401        assert_equal(0, len(expected_flushes))
402
403        self.log.info("restart the node with -prune")
404        self.start_node(0, ["-fastprune=1", "-prune=1"])
405
406        BLOCKS_TO_MINE = 350
407        self.log.info(f"mine {BLOCKS_TO_MINE} blocks to be able to prune")
408        self.generate(self.wallet, BLOCKS_TO_MINE)
409
410        self.log.info("test the utxocache:flush tracepoint API with pruning")
411        self.log.info("hook into the utxocache:flush tracepoint")
412        ctx = USDT(pid=self.nodes[0].process.pid)
413        ctx.enable_probe(probe="utxocache:flush",
414                         fn_name="trace_utxocache_flush")
415        bpf = BPF(text=utxocache_flushes_program, usdt_contexts=[ctx], debug=0, cflags=bpf_cflags())
416        bpf["utxocache_flush"].open_perf_buffer(handle_utxocache_flush)
417
418        self.log.info("prune blockchain to trigger a flush for pruning")
419        expected_flushes.append({"mode": "NONE", "for_prune": True, "size": BLOCKS_TO_MINE})
420        self.nodes[0].pruneblockchain(315)
421
422        bpf.perf_buffer_poll(timeout=500)
423        bpf.cleanup()
424
425        self.log.info(
426            "check that we don't expect additional flushes and that the handle_* function succeeded")
427        assert_equal(0, len(expected_flushes))
428        assert_equal(EXPECTED_HANDLE_FLUSH_SUCCESS, handle_flush_succeeds)
429
430
431if __name__ == '__main__':
432    UTXOCacheTracepointTest(__file__).main()
433