interface_usdt_utxocache.py raw
1 #!/usr/bin/env python3
2 # Copyright (c) 2022-present The Limenka 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/limenka/limenka/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 LimenkaTestFramework
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: "ALWAYS",
113 }
114
115
116 class UTXOCacheChange(ctypes.Structure):
117 _fields_ = [
118 ("txid", ctypes.c_ubyte * 32),
119 ("index", ctypes.c_uint32),
120 ("height", ctypes.c_uint32),
121 ("value", ctypes.c_uint64),
122 ("is_coinbase", ctypes.c_bool),
123 ]
124
125 def __repr__(self):
126 return f"UTXOCacheChange(outpoint={bytes(self.txid[::-1]).hex()}:{self.index}, height={self.height}, value={self.value}sat, is_coinbase={self.is_coinbase})"
127
128
129 class UTXOCacheFlush(ctypes.Structure):
130 _fields_ = [
131 ("duration", ctypes.c_int64),
132 ("mode", ctypes.c_uint32),
133 ("size", ctypes.c_uint64),
134 ("memory", ctypes.c_uint64),
135 ("for_prune", ctypes.c_bool),
136 ]
137
138 def __repr__(self):
139 return f"UTXOCacheFlush(duration={self.duration}, mode={FLUSHMODE_NAME[self.mode]}, size={self.size}, memory={self.memory}, for_prune={self.for_prune})"
140
141
142 class UTXOCacheTracepointTest(LimenkaTestFramework):
143 def set_test_params(self):
144 self.setup_clean_chain = False
145 self.num_nodes = 1
146 self.extra_args = [["-txindex"]]
147
148 def skip_test_if_missing_module(self):
149 self.skip_if_platform_not_linux()
150 self.skip_if_no_limenkad_tracepoints()
151 self.skip_if_no_python_bcc()
152 self.skip_if_no_bpf_permissions()
153
154 def run_test(self):
155 self.wallet = MiniWallet(self.nodes[0])
156
157 self.test_uncache()
158 self.test_add_spent()
159 self.test_flush()
160
161 def test_uncache(self):
162 """ Tests the utxocache:uncache tracepoint API.
163 https://github.com/limenka/limenka/blob/master/doc/tracing.md#tracepoint-utxocacheuncache
164 """
165 # To trigger an UTXO uncache from the cache, we create an invalid transaction
166 # spending a not-cached, but existing UTXO. During transaction validation, this
167 # the UTXO is added to the utxo cache, but as the transaction is invalid, it's
168 # uncached again.
169 self.log.info("testing the utxocache:uncache tracepoint API")
170
171 # Retrieve the txid for the UTXO created in the first block. This UTXO is not
172 # in our UTXO cache.
173 EARLY_BLOCK_HEIGHT = 1
174 block_1_hash = self.nodes[0].getblockhash(EARLY_BLOCK_HEIGHT)
175 block_1 = self.nodes[0].getblock(block_1_hash)
176 block_1_coinbase_txid = block_1["tx"][0]
177
178 # Create a transaction and invalidate it by changing the txid of the previous
179 # output to the coinbase txid of the block at height 1.
180 invalid_tx = self.wallet.create_self_transfer()["tx"]
181 invalid_tx.vin[0].prevout.hash = int(block_1_coinbase_txid, 16)
182
183 self.log.info("hooking into the utxocache:uncache tracepoint")
184 ctx = USDT(pid=self.nodes[0].process.pid)
185 ctx.enable_probe(probe="utxocache:uncache",
186 fn_name="trace_utxocache_uncache")
187 bpf = BPF(text=utxocache_changes_program, usdt_contexts=[ctx], debug=0, cflags=bpf_cflags())
188
189 # The handle_* function is a ctypes callback function called from C. When
190 # we assert in the handle_* function, the AssertError doesn't propagate
191 # back to Python. The exception is ignored. We manually count and assert
192 # that the handle_* functions succeeded.
193 EXPECTED_HANDLE_UNCACHE_SUCCESS = 1
194 handle_uncache_succeeds = 0
195
196 def handle_utxocache_uncache(_, data, __):
197 nonlocal handle_uncache_succeeds
198 event = ctypes.cast(data, ctypes.POINTER(UTXOCacheChange)).contents
199 self.log.info(f"handle_utxocache_uncache(): {event}")
200 try:
201 assert_equal(block_1_coinbase_txid, bytes(event.txid[::-1]).hex())
202 assert_equal(0, event.index) # prevout index
203 assert_equal(EARLY_BLOCK_HEIGHT, event.height)
204 assert_equal(50 * COIN, event.value)
205 assert_equal(True, event.is_coinbase)
206 except AssertionError:
207 self.log.exception("Assertion failed")
208 else:
209 handle_uncache_succeeds += 1
210
211 bpf["utxocache_uncache"].open_perf_buffer(handle_utxocache_uncache)
212
213 self.log.info(
214 "testmempoolaccept the invalid transaction to trigger an UTXO-cache uncache")
215 result = self.nodes[0].testmempoolaccept(
216 [invalid_tx.serialize().hex()])[0]
217 assert_equal(result["allowed"], False)
218
219 bpf.perf_buffer_poll(timeout=100)
220 bpf.cleanup()
221
222 self.log.info(
223 f"check that we successfully traced {EXPECTED_HANDLE_UNCACHE_SUCCESS} uncaches")
224 assert_equal(EXPECTED_HANDLE_UNCACHE_SUCCESS, handle_uncache_succeeds)
225
226 def test_add_spent(self):
227 """ Tests the utxocache:add utxocache:spent tracepoint API
228 See https://github.com/limenka/limenka/blob/master/doc/tracing.md#tracepoint-utxocacheadd
229 and https://github.com/limenka/limenka/blob/master/doc/tracing.md#tracepoint-utxocachespent
230 """
231
232 self.log.info(
233 "test the utxocache:add and utxocache:spent tracepoint API")
234
235 self.log.info("create an unconfirmed transaction")
236 self.wallet.send_self_transfer(from_node=self.nodes[0])
237
238 # We mine a block to trace changes (add/spent) to the active in-memory cache
239 # of the UTXO set (see CoinsTip() of CCoinsViewCache). However, in some cases
240 # temporary clones of the active cache are made. For example, during mining with
241 # the generate RPC call, the block is first tested in TestBlockValidity(). There,
242 # a clone of the active cache is modified during a test ConnectBlock() call.
243 # These are implementation details we don't want to test here. Thus, after
244 # mining, we invalidate the block, start the tracing, and then trace the cache
245 # changes to the active utxo cache.
246 self.log.info("mine and invalidate a block that is later reconsidered")
247 block_hash = self.generate(self.wallet, 1)[0]
248 self.nodes[0].invalidateblock(block_hash)
249
250 self.log.info(
251 "hook into the utxocache:add and utxocache:spent tracepoints")
252 ctx = USDT(pid=self.nodes[0].process.pid)
253 ctx.enable_probe(probe="utxocache:add", fn_name="trace_utxocache_add")
254 ctx.enable_probe(probe="utxocache:spent",
255 fn_name="trace_utxocache_spent")
256 bpf = BPF(text=utxocache_changes_program, usdt_contexts=[ctx], debug=0, cflags=bpf_cflags())
257
258 # The handle_* function is a ctypes callback function called from C. When
259 # we assert in the handle_* function, the AssertError doesn't propagate
260 # back to Python. The exception is ignored. We manually count and assert
261 # that the handle_* functions succeeded.
262 EXPECTED_HANDLE_ADD_SUCCESS = 2
263 EXPECTED_HANDLE_SPENT_SUCCESS = 1
264
265 expected_utxocache_adds = []
266 expected_utxocache_spents = []
267
268 actual_utxocache_adds = []
269 actual_utxocache_spents = []
270
271 def compare_utxo_with_event(utxo, event):
272 """Compare a utxo dict to the event produced by BPF"""
273 assert_equal(utxo["txid"], bytes(event.txid[::-1]).hex())
274 assert_equal(utxo["index"], event.index)
275 assert_equal(utxo["height"], event.height)
276 assert_equal(utxo["value"], event.value)
277 assert_equal(utxo["is_coinbase"], event.is_coinbase)
278
279 def handle_utxocache_add(_, data, __):
280 event = ctypes.cast(data, ctypes.POINTER(UTXOCacheChange)).contents
281 self.log.info(f"handle_utxocache_add(): {event}")
282 actual_utxocache_adds.append(event)
283
284 def handle_utxocache_spent(_, data, __):
285 event = ctypes.cast(data, ctypes.POINTER(UTXOCacheChange)).contents
286 self.log.info(f"handle_utxocache_spent(): {event}")
287 actual_utxocache_spents.append(event)
288
289 bpf["utxocache_add"].open_perf_buffer(handle_utxocache_add)
290 bpf["utxocache_spent"].open_perf_buffer(handle_utxocache_spent)
291
292 # We trigger a block re-connection. This causes changes (add/spent)
293 # to the UTXO-cache which in turn triggers the tracepoints.
294 self.log.info("reconsider the previously invalidated block")
295 self.nodes[0].reconsiderblock(block_hash)
296
297 block = self.nodes[0].getblock(block_hash, 2)
298 for (block_index, tx) in enumerate(block["tx"]):
299 for vin in tx["vin"]:
300 if "coinbase" not in vin:
301 prevout_tx = self.nodes[0].getrawtransaction(
302 vin["txid"], True)
303 prevout_tx_block = self.nodes[0].getblockheader(
304 prevout_tx["blockhash"])
305 spends_coinbase = "coinbase" in prevout_tx["vin"][0]
306 expected_utxocache_spents.append({
307 "txid": vin["txid"],
308 "index": vin["vout"],
309 "height": prevout_tx_block["height"],
310 "value": int(prevout_tx["vout"][vin["vout"]]["value"] * COIN),
311 "is_coinbase": spends_coinbase,
312 })
313 for (i, vout) in enumerate(tx["vout"]):
314 if vout["scriptPubKey"]["type"] != "nulldata":
315 expected_utxocache_adds.append({
316 "txid": tx["txid"],
317 "index": i,
318 "height": block["height"],
319 "value": int(vout["value"] * COIN),
320 "is_coinbase": block_index == 0,
321 })
322
323 bpf.perf_buffer_poll(timeout=200)
324
325 assert_equal(EXPECTED_HANDLE_ADD_SUCCESS, len(expected_utxocache_adds), len(actual_utxocache_adds))
326 assert_equal(EXPECTED_HANDLE_SPENT_SUCCESS, len(expected_utxocache_spents), len(actual_utxocache_spents))
327
328 self.log.info(
329 f"check that we successfully traced {EXPECTED_HANDLE_ADD_SUCCESS} adds and {EXPECTED_HANDLE_SPENT_SUCCESS} spent")
330 for expected_utxo, actual_event in zip(expected_utxocache_adds + expected_utxocache_spents,
331 actual_utxocache_adds + actual_utxocache_spents):
332 compare_utxo_with_event(expected_utxo, actual_event)
333
334 bpf.cleanup()
335
336 def test_flush(self):
337 """ Tests the utxocache:flush tracepoint API.
338 See https://github.com/limenka/limenka/blob/master/doc/tracing.md#tracepoint-utxocacheflush"""
339
340 self.log.info("test the utxocache:flush tracepoint API")
341 self.log.info("hook into the utxocache:flush tracepoint")
342 ctx = USDT(pid=self.nodes[0].process.pid)
343 ctx.enable_probe(probe="utxocache:flush",
344 fn_name="trace_utxocache_flush")
345 bpf = BPF(text=utxocache_flushes_program, usdt_contexts=[ctx], debug=0, cflags=bpf_cflags())
346
347 # The handle_* function is a ctypes callback function called from C. When
348 # we assert in the handle_* function, the AssertError doesn't propagate
349 # back to Python. The exception is ignored. We manually count and assert
350 # that the handle_* functions succeeded.
351 EXPECTED_HANDLE_FLUSH_SUCCESS = 3
352 handle_flush_succeeds = 0
353 expected_flushes = list()
354
355 def handle_utxocache_flush(_, data, __):
356 nonlocal handle_flush_succeeds
357 event = ctypes.cast(data, ctypes.POINTER(UTXOCacheFlush)).contents
358 self.log.info(f"handle_utxocache_flush(): {event}")
359 expected_flushes.remove({
360 "mode": FLUSHMODE_NAME[event.mode],
361 "for_prune": event.for_prune,
362 "size": event.size
363 })
364 # sanity checks only
365 try:
366 assert event.memory > 0
367 assert event.duration > 0
368 except AssertionError:
369 self.log.exception("Assertion error")
370 else:
371 handle_flush_succeeds += 1
372
373 bpf["utxocache_flush"].open_perf_buffer(handle_utxocache_flush)
374
375 self.log.info("stop the node to flush the UTXO cache")
376 UTXOS_IN_CACHE = 2 # might need to be changed if the earlier tests are modified
377 # A node shutdown causes two flushes. One that flushes UTXOS_IN_CACHE
378 # UTXOs and one that flushes 0 UTXOs. Normally the 0-UTXO-flush is the
379 # second flush, however it can happen that the order changes.
380 expected_flushes.append({"mode": "ALWAYS", "for_prune": False, "size": UTXOS_IN_CACHE})
381 expected_flushes.append({"mode": "ALWAYS", "for_prune": False, "size": 0})
382 self.stop_node(0)
383
384 bpf.perf_buffer_poll(timeout=200)
385 bpf.cleanup()
386
387 self.log.info("check that we don't expect additional flushes")
388 assert_equal(0, len(expected_flushes))
389
390 self.log.info("restart the node with -prune")
391 self.start_node(0, ["-fastprune=1", "-prune=1"])
392
393 BLOCKS_TO_MINE = 350
394 self.log.info(f"mine {BLOCKS_TO_MINE} blocks to be able to prune")
395 self.generate(self.wallet, BLOCKS_TO_MINE)
396
397 self.log.info("test the utxocache:flush tracepoint API with pruning")
398 self.log.info("hook into the utxocache:flush tracepoint")
399 ctx = USDT(pid=self.nodes[0].process.pid)
400 ctx.enable_probe(probe="utxocache:flush",
401 fn_name="trace_utxocache_flush")
402 bpf = BPF(text=utxocache_flushes_program, usdt_contexts=[ctx], debug=0, cflags=bpf_cflags())
403 bpf["utxocache_flush"].open_perf_buffer(handle_utxocache_flush)
404
405 self.log.info("prune blockchain to trigger a flush for pruning")
406 expected_flushes.append({"mode": "NONE", "for_prune": True, "size": 0})
407 self.nodes[0].pruneblockchain(315)
408
409 bpf.perf_buffer_poll(timeout=500)
410 bpf.cleanup()
411
412 self.log.info(
413 "check that we don't expect additional flushes and that the handle_* function succeeded")
414 assert_equal(0, len(expected_flushes))
415 assert_equal(EXPECTED_HANDLE_FLUSH_SUCCESS, handle_flush_succeeds)
416
417
418 if __name__ == '__main__':
419 UTXOCacheTracepointTest(__file__).main()
420