interface_usdt_utxocache.py raw
1 #!/usr/bin/env python3
2 # Copyright (c) 2022-present The Bitcoin Core developers
3 # Distributed under the MIT software license, see the accompanying
4 # file COPYING or http://www.opensource.org/licenses/mit-license.php.
5
6 """ Tests the utxocache:* tracepoint API interface.
7 See https://github.com/bitcoin/bitcoin/blob/master/doc/tracing.md#context-utxocache
8 """
9
10 import ctypes
11 # Test will be skipped if we don't have bcc installed
12 try:
13 from bcc import BPF, USDT # type: ignore[import]
14 except ImportError:
15 pass
16 from test_framework.messages import COIN
17 from test_framework.test_framework import BitcoinTestFramework
18 from test_framework.util import (
19 assert_equal,
20 bpf_cflags,
21 )
22 from test_framework.wallet import MiniWallet
23
24 utxocache_changes_program = """
25 #include <uapi/linux/ptrace.h>
26
27 typedef signed long long i64;
28
29 struct utxocache_change
30 {
31 char txid[32];
32 u32 index;
33 u32 height;
34 i64 value;
35 bool is_coinbase;
36 };
37
38 BPF_PERF_OUTPUT(utxocache_add);
39 int trace_utxocache_add(struct pt_regs *ctx) {
40 struct utxocache_change add = {};
41 void *ptxid = NULL;
42 bpf_usdt_readarg(1, ctx, &ptxid);
43 bpf_probe_read_user(&add.txid, sizeof(add.txid), ptxid);
44 bpf_usdt_readarg(2, ctx, &add.index);
45 bpf_usdt_readarg(3, ctx, &add.height);
46 bpf_usdt_readarg(4, ctx, &add.value);
47 bpf_usdt_readarg(5, ctx, &add.is_coinbase);
48 utxocache_add.perf_submit(ctx, &add, sizeof(add));
49 return 0;
50 }
51
52 BPF_PERF_OUTPUT(utxocache_spent);
53 int trace_utxocache_spent(struct pt_regs *ctx) {
54 struct utxocache_change spent = {};
55 void *ptxid = NULL;
56 bpf_usdt_readarg(1, ctx, &ptxid);
57 bpf_probe_read_user(&spent.txid, sizeof(spent.txid), ptxid);
58 bpf_usdt_readarg(2, ctx, &spent.index);
59 bpf_usdt_readarg(3, ctx, &spent.height);
60 bpf_usdt_readarg(4, ctx, &spent.value);
61 bpf_usdt_readarg(5, ctx, &spent.is_coinbase);
62 utxocache_spent.perf_submit(ctx, &spent, sizeof(spent));
63 return 0;
64 }
65
66 BPF_PERF_OUTPUT(utxocache_uncache);
67 int trace_utxocache_uncache(struct pt_regs *ctx) {
68 struct utxocache_change uncache = {};
69 void *ptxid = NULL;
70 bpf_usdt_readarg(1, ctx, &ptxid);
71 bpf_probe_read_user(&uncache.txid, sizeof(uncache.txid), ptxid);
72 bpf_usdt_readarg(2, ctx, &uncache.index);
73 bpf_usdt_readarg(3, ctx, &uncache.height);
74 bpf_usdt_readarg(4, ctx, &uncache.value);
75 bpf_usdt_readarg(5, ctx, &uncache.is_coinbase);
76 utxocache_uncache.perf_submit(ctx, &uncache, sizeof(uncache));
77 return 0;
78 }
79 """
80
81 utxocache_flushes_program = """
82 #include <uapi/linux/ptrace.h>
83
84 typedef signed long long i64;
85
86 struct utxocache_flush
87 {
88 i64 duration;
89 u32 mode;
90 u64 size;
91 u64 memory;
92 bool for_prune;
93 };
94
95 BPF_PERF_OUTPUT(utxocache_flush);
96 int trace_utxocache_flush(struct pt_regs *ctx) {
97 struct utxocache_flush flush = {};
98 bpf_usdt_readarg(1, ctx, &flush.duration);
99 bpf_usdt_readarg(2, ctx, &flush.mode);
100 bpf_usdt_readarg(3, ctx, &flush.size);
101 bpf_usdt_readarg(4, ctx, &flush.memory);
102 bpf_usdt_readarg(5, ctx, &flush.for_prune);
103 utxocache_flush.perf_submit(ctx, &flush, sizeof(flush));
104 return 0;
105 }
106 """
107
108 FLUSHMODE_NAME = {
109 0: "NONE",
110 1: "IF_NEEDED",
111 2: "PERIODIC",
112 3: "FORCE_FLUSH",
113 4: "FORCE_SYNC",
114 }
115
116
117 class UTXOCacheChange(ctypes.Structure):
118 _fields_ = [
119 ("txid", ctypes.c_ubyte * 32),
120 ("index", ctypes.c_uint32),
121 ("height", ctypes.c_uint32),
122 ("value", ctypes.c_uint64),
123 ("is_coinbase", ctypes.c_bool),
124 ]
125
126 def __repr__(self):
127 return f"UTXOCacheChange(outpoint={bytes(self.txid[::-1]).hex()}:{self.index}, height={self.height}, value={self.value}sat, is_coinbase={self.is_coinbase})"
128
129
130 class UTXOCacheFlush(ctypes.Structure):
131 _fields_ = [
132 ("duration", ctypes.c_int64),
133 ("mode", ctypes.c_uint32),
134 ("size", ctypes.c_uint64),
135 ("memory", ctypes.c_uint64),
136 ("for_prune", ctypes.c_bool),
137 ]
138
139 def __repr__(self):
140 return f"UTXOCacheFlush(duration={self.duration}, mode={FLUSHMODE_NAME[self.mode]}, size={self.size}, memory={self.memory}, for_prune={self.for_prune})"
141
142
143 class UTXOCacheTracepointTest(BitcoinTestFramework):
144 def set_test_params(self):
145 self.setup_clean_chain = False
146 self.num_nodes = 1
147 self.extra_args = [["-txindex"]]
148
149 def skip_test_if_missing_module(self):
150 self.skip_if_platform_not_linux()
151 self.skip_if_no_bitcoind_tracepoints()
152 self.skip_if_no_python_bcc()
153 self.skip_if_no_bpf_permissions()
154 self.skip_if_running_under_valgrind()
155
156 def run_test(self):
157 self.wallet = MiniWallet(self.nodes[0])
158
159 self.test_uncache()
160 self.test_add_spent()
161 self.test_flush()
162
163 def test_uncache(self):
164 """ Tests the utxocache:uncache tracepoint API.
165 https://github.com/bitcoin/bitcoin/blob/master/doc/tracing.md#tracepoint-utxocacheuncache
166 """
167 # To trigger an UTXO uncache from the cache, we create an invalid transaction
168 # spending a not-cached, but existing UTXO. During transaction validation, this
169 # the UTXO is added to the utxo cache, but as the transaction is invalid, it's
170 # uncached again.
171 self.log.info("testing the utxocache:uncache tracepoint API")
172
173 # Retrieve the txid for the UTXO created in the first block. This UTXO is not
174 # in our UTXO cache.
175 EARLY_BLOCK_HEIGHT = 1
176 block_1_hash = self.nodes[0].getblockhash(EARLY_BLOCK_HEIGHT)
177 block_1 = self.nodes[0].getblock(block_1_hash)
178 block_1_coinbase_txid = block_1["tx"][0]
179
180 # Create a transaction and invalidate it by changing the txid of the previous
181 # output to the coinbase txid of the block at height 1.
182 invalid_tx = self.wallet.create_self_transfer()["tx"]
183 invalid_tx.vin[0].prevout.hash = int(block_1_coinbase_txid, 16)
184
185 self.log.info("hooking into the utxocache:uncache tracepoint")
186 ctx = USDT(pid=self.nodes[0].process.pid)
187 ctx.enable_probe(probe="utxocache:uncache",
188 fn_name="trace_utxocache_uncache")
189 bpf = BPF(text=utxocache_changes_program, usdt_contexts=[ctx], debug=0, cflags=bpf_cflags())
190
191 # The handle_* function is a ctypes callback function called from C. When
192 # we assert in the handle_* function, the AssertError doesn't propagate
193 # back to Python. The exception is ignored. We manually count and assert
194 # that the handle_* functions succeeded.
195 EXPECTED_HANDLE_UNCACHE_SUCCESS = 1
196 handle_uncache_succeeds = 0
197
198 def handle_utxocache_uncache(_, data, __):
199 nonlocal handle_uncache_succeeds
200 event = ctypes.cast(data, ctypes.POINTER(UTXOCacheChange)).contents
201 self.log.info(f"handle_utxocache_uncache(): {event}")
202 try:
203 assert_equal(block_1_coinbase_txid, bytes(event.txid[::-1]).hex())
204 assert_equal(0, event.index) # prevout index
205 assert_equal(EARLY_BLOCK_HEIGHT, event.height)
206 assert_equal(50 * COIN, event.value)
207 assert_equal(True, event.is_coinbase)
208 except AssertionError:
209 self.log.exception("Assertion failed")
210 else:
211 handle_uncache_succeeds += 1
212
213 bpf["utxocache_uncache"].open_perf_buffer(handle_utxocache_uncache)
214
215 self.log.info(
216 "testmempoolaccept the invalid transaction to trigger an UTXO-cache uncache")
217 result = self.nodes[0].testmempoolaccept(
218 [invalid_tx.serialize().hex()])[0]
219 assert_equal(result["allowed"], False)
220
221 bpf.perf_buffer_poll(timeout=100)
222 bpf.cleanup()
223
224 self.log.info(
225 f"check that we successfully traced {EXPECTED_HANDLE_UNCACHE_SUCCESS} uncaches")
226 assert_equal(EXPECTED_HANDLE_UNCACHE_SUCCESS, handle_uncache_succeeds)
227
228 def test_add_spent(self):
229 """ Tests the utxocache:add utxocache:spent tracepoint API
230 See https://github.com/bitcoin/bitcoin/blob/master/doc/tracing.md#tracepoint-utxocacheadd
231 and https://github.com/bitcoin/bitcoin/blob/master/doc/tracing.md#tracepoint-utxocachespent
232 """
233
234 self.log.info(
235 "test the utxocache:add and utxocache:spent tracepoint API")
236
237 self.log.info("create an unconfirmed transaction")
238 self.wallet.send_self_transfer(from_node=self.nodes[0])
239
240 # We mine a block to trace changes (add/spent) to the active in-memory cache
241 # of the UTXO set (see CoinsTip() of CCoinsViewCache). However, in some cases
242 # temporary clones of the active cache are made. For example, during mining with
243 # the generate RPC call, the block is first tested in TestBlockValidity(). There,
244 # a clone of the active cache is modified during a test ConnectBlock() call.
245 # These are implementation details we don't want to test here. Thus, after
246 # mining, we invalidate the block, start the tracing, and then trace the cache
247 # changes to the active utxo cache.
248 self.log.info("mine and invalidate a block that is later reconsidered")
249 block_hash = self.generate(self.wallet, 1)[0]
250 self.nodes[0].invalidateblock(block_hash)
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
431 if __name__ == '__main__':
432 UTXOCacheTracepointTest(__file__).main()
433