bitcoin: Intermittent failures in interface_usdt_mempool.py

https://cirrus-ci.com/task/6053265947754496 ? 😢

Maybe it will “fix itself” after #27360 ?

Unfortunately, it didn’t (https://github.com/bitcoin/bitcoin/runs/13206824577 from master after #27360 was merged)

Have seen this a couple times by now.

cc @0xB10C @virtu

neither tx nor result go out of scope before it’s called

I don’t think the lifetime of result is relevant here. GetRejectReason() gives birth to a fresh temporary copy of the string, having its own lifetime.

All that said, it’s obviously still going wrong somehow…

Yeah, I am just guessing that this is a lifetime issue. It would be good to rule this out.

AFAIU the macros themselves don’t copy any data, rather just define a static probe point. Any arguments passed to them just get incorporated into the assembly code. The tracing program (BPF) if loaded into the kernel can run code at the trace points. Here it can choose to, and AFAIU does in our case with BPF, copy the data into a different kernel space map when it hits a tracepoint, which can then be read by the USDT probe in our python test.

So the data does get copied but not by the macro, rather by the BPF program.

https://cirrus-ci.com/task/4626519738286080?logs=ci#L3262

 node0 2023-06-29T19:45:37.525879Z (mocktime: 2023-07-13T19:45:38Z) [httpworker.2] [rpc/request.cpp:181] [parse] [rpc] ThreadRPCServer method=getrawmempool user=__cookie__ 
 test  2023-06-29T19:45:37.526000Z TestFramework (INFO): Polling buffer... 
 test  2023-06-29T19:45:37.527000Z TestFramework (INFO): Ensuring mempool:rejected event was handled successfully... 
 test  2023-06-29T19:45:37.527000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 131, in main
                                       self.run_test()
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/interface_usdt_mempool.py", line 329, in run_test
                                       self.rejected_test()
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/interface_usdt_mempool.py", line 310, in rejected_test
                                       assert_equal(event.reason.decode("UTF-8"), "min relay fee not met")
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/util.py", line 57, in assert_equal
                                       raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
                                   AssertionError: not( == min relay fee not met)

https://github.com/bitcoin/bitcoin/pull/27831 improves the logging, probably.

Can it be forced to “reproduce” on master by adding a typo to the error string in assert_equal?

see https://github.com/0xB10C/bitcoin/commit/4091d621f16b6316eef5551a56c00bf0e2c0e541 and this CI task https://cirrus-ci.com/task/4909169740873728

@0xB10C and I had a look at this today. Here’s what we found so far:

1. We believe the issue is caused by one or more of the assertions failing in the handle_rejected_event callback (although we are not sure why they fail).
2. The test framework’s assert_equal() communicates failed assertions via exceptions. Unfortunately exceptions raised in bcc callback functions are not properly propagated (Exception ignored on calling ctypes callback function: <function PerfEventArray._open_perf_buffer.<locals>.raw_cb_ at 0xffff83490e50>), so they only appear on stderr, not in the logs. As a consequence, the logs only show that the test case failed, not why it failed.
3. Because (2) is a general problem with functional tests for tracepoints, I’ll create a PR that fixes the issue for all of them. The best solution we came up with so far is wrapping all assert_equals() in bcc callback functions in try blocks and logging any AssertionError exceptions using self.log(). Once this (or a better solution, preferable one that involves not ignoring exceptions in ctype callback functions, if that’s possible) is merged, the logs should tell us why the mempool:rejected test fails sporadically.

master @ e0a70c5b4f2c691e8d6b507c8ce879f0b0424254. https://cirrus-ci.com/task/5247512164958208:

 node0 2023-05-10T17:29:06.449483Z (mocktime: 2023-05-24T17:29:09Z) [httpworker.1] [rpc/request.cpp:181] [parse] [rpc] ThreadRPCServer method=getrawmempool user=__cookie__ 
 test  2023-05-10T17:29:06.450000Z TestFramework (INFO): Polling buffer... 
 test  2023-05-10T17:29:06.486000Z TestFramework (INFO): Ensuring mempool:rejected event was handled successfully... 
 test  2023-05-10T17:29:06.486000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
                                       self.run_test()
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/interface_usdt_mempool.py", line 339, in run_test
                                       self.rejected_test()
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/interface_usdt_mempool.py", line 323, in rejected_test
                                       assert_equal(EXPECTED_REJECTED_EVENTS, handled_rejected_events)
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/util.py", line 55, in assert_equal
                                       raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
                                   AssertionError: not(1 == 0)
 test  2023-05-10T17:29:06.487000Z TestFramework (DEBUG): Closing down network thread
...
interface_usdt_mempool.py                              | ✖ Failed  | 5 s

Again here https://cirrus-ci.com/task/5250935128064000?logs=ci#L3275