ci: failure in interface_usdt

fanquake commented at 2:44 pm on February 25, 2025: member

https://github.com/bitcoin/bitcoin/actions/runs/13501527489/job/37720897174?pr=31945:

 0UTXOCacheChange(outpoint=fab2396e3f726e1801b9e7303cf294783a3fd7e19ddc8f2dfa55e25b01575b3e:0, height=77, value=5000000000sat, is_coinbase=True) 
 1 test  2025-02-24T16:25:34.721000Z TestFramework (INFO): check that we successfully traced 2 adds and 1 spent 
 2 test  2025-02-24T16:25:34.721000Z TestFramework (ERROR): Assertion failed 
 3                                   Traceback (most recent call last):
 4                                     File "/home/runner/work/_temp/test/functional/test_framework/test_framework.py", line 135, in main
 5                                       self.run_test()
 6                                     File "/home/runner/work/_temp/build-asan/test/functional/interface_usdt_utxocache.py", line 149, in run_test
 7                                       self.test_add_spent()
 8                                     File "/home/runner/work/_temp/build-asan/test/functional/interface_usdt_utxocache.py", line 323, in test_add_spent
 9                                       compare_utxo_with_event(expected_utxo, actual_event)
10                                     File "/home/runner/work/_temp/build-asan/test/functional/interface_usdt_utxocache.py", line 264, in compare_utxo_with_event
11                                       assert_equal(utxo["txid"], bytes(event.txid[::-1]).hex())
12                                     File "/home/runner/work/_temp/test/functional/test_framework/util.py", line 77, in assert_equal
13                                       raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
14                                   AssertionError: not(23b3dfef15c9b64445ffd44920adc48e7746aff1f03b59db3ed71936e90ff201 == d09ca39938b434b19a3338ef6b410071d85d4450dd7dc1f7db1bf7d95a53709a)
15 test  2025-02-24T16:25:34.746000Z TestFramework (DEBUG): Closing down network thread

maflcko added the label CI failed on Feb 25, 2025

maflcko added the label interfaces on Feb 25, 2025

bitcoin deleted a comment on Feb 25, 2025

0xB10C commented at 1:50 am on February 26, 2025: contributor

Based on the logs just before the assert:

0TestFramework (INFO): handle_utxocache_add(): UTXOCacheChange(outpoint=d09ca39938b434b19a3338ef6b410071d85d4450dd7dc1f7db1bf7d95a53709a:0, height=201, value=4999968800sat, is_coinbase=False) 
1TestFramework (INFO): handle_utxocache_add(): UTXOCacheChange(outpoint=23b3dfef15c9b64445ffd44920adc48e7746aff1f03b59db3ed71936e90ff201:0, height=201, value=2500031200sat, is_coinbase=True) 
2TestFramework (INFO): handle_utxocache_spent(): UTXOCacheChange(outpoint=fab2396e3f726e1801b9e7303cf294783a3fd7e19ddc8f2dfa55e25b01575b3e:0, height=77, value=5000000000sat, is_coinbase=True) 
3TestFramework (INFO): check that we successfully traced 2 adds and 1 spent 
4[...]
5AssertionError: not(23b3dfef15c9b64445ffd44920adc48e7746aff1f03b59db3ed71936e90ff201 == d09ca39938b434b19a3338ef6b410071d85d4450dd7dc1f7db1bf7d95a53709a)

It seems like we learned about d09ca3.. and then about fab239.. but expected the order to be the other way around. This makes sense, since fab239.. is a coinbase UTXO which is added first. Unclear why the order was mixed in this case.

https://github.com/bitcoin/bitcoin/blob/0bb8a01810ec6f602b32d4677fa5004e12e0f538/test/functional/interface_usdt_utxocache.py#L319-L323

A simple solution could be to not depend on the order of the tracepoint event arrival. As long as all expected events are received, pass the test.

willcl-ark commented at 11:53 am on March 20, 2025: member

From reading up on this a little it seems to be possible that if the tracepoint:

includes runtime lookups
is executed in a multi-threaded (or multi-CPU) environment
(possibly other factors)

…then it may not be possible to totally guarantee ordering at userspace collection points. One can use BPF queues, but I suspect this wouldn’t solve our problem here.

I think if we wanted guaranteed ordering we may have to do something like add a nanosecond timestamp to each tracepoint, buffer them in the bpf program, and sort based on timestamp before processing in userspace.

However, I don’t think we need that and agree that we should probably just:

not depend on the order of the tracepoint event arrival. As long as all expected events are received, pass the test.

Would we want to make all the usdt tests order-independent, or only this one? We have strict ordering in others, e.g.

https://github.com/bitcoin/bitcoin/blob/aa87e0b44600a32b32a4b123d4f90d097f1f106f/test/functional/interface_usdt_coinselection.py#L184-L237

To change only this test is relatviely simple: https://github.com/bitcoin/bitcoin/compare/master...willcl-ark:bitcoin:usdt-order-independant but it will be more work to apply to all the tests…

0xB10C commented at 12:04 pm on March 20, 2025: contributor

To change only this test is relatviely simple: https://github.com/bitcoin/bitcoin/compare/master...willcl-ark:bitcoin:usdt-order-independant but it will be more work to apply to all the tests…

This was the first, and for now, the only time we saw this test fail due to ordering problems. I think we can’t completely rule out ordering problems, but IMO it would be good to see this happening in some other test(s) before we start changing them.

willcl-ark referenced this in commit 693d1e2f54 on Mar 20, 2025

willcl-ark referenced this in commit 8d2a309860 on Mar 26, 2025

willcl-ark referenced this in commit 248fdd88dc on Mar 26, 2025

fanquake closed this on Mar 27, 2025

ci: failure in interface_usdt_utxocache.py #31951