test: handle failed assert_equal() assertions in bcc callback functions #27831

pull virtu wants to merge 1 commits into bitcoin:master from virtu:handle_bcc_callback_exceptions changing 4 files +88 −90
  1. virtu commented at 8:33 am on June 6, 2023: contributor

    Address #27380 (and similar future issues) by handling failed assert_equal() assertions in bcc callback functions

    Problem

    Exceptions are not propagated in ctype callback functions used by bcc. This means an AssertionError exception raised by assert_equal() to signal a failed assertion is not getting caught and properly logged. Instead, the error is logged to stdout and execution of the callback stops.

    The current workaround to check whether all assert_equal() assertions in a callback succeeded is to increment a success counter after the assertions (which only gets incremented if none exception is raised and stops execution). Then, outside the callback, the success counter can be used to check whether a callback executed successfully.

    One issue with the described workaround is that when an exception occurs, there is no way of telling which of the assert_equal() statements caused the exception; moreover, there is no way of inspecting how the pieces of data that got compared in assert_equal() differed (often a crucial clue when debugging what went wrong).

    This problem is happening in #27380: Sporadically, in the mempool:rejected test, execution does not reach the end of the callback function and the success counter is not incremented. Thus, the test fails when comparing the counter to its expected value of one. Without knowing which of the asserts failed any why it failed, this issue is hard to debug.

    Solution

    Two fixes come to mind. The first involves having the callback function make event data accessible outside the callback and inspecting the event using assert_equal() outside the callback. This solution still requires a counter in the callback in order to tell whether a callback was actually executed or if instead the call to perf_buffer_poll() timed out.

    The second fix entails wrapping all relevant assert_equal() statements inside callback functions into try-catch blocks and manually logging AssertionErrors. While not as elegant in terms of design, this approach can be more pragmatic for more complex tests (e.g., ones involving multiple events, events of different types, or the order of events).

    The solution proposed here is to select the most pragmatic fix on a case-by-case basis: Tests in interface_usdt_net.py, interface_usdt_mempool.py and interface_usdt_validation.py have been refactored to use the first approach, while the second approach was chosen for interface_usdt_utxocache.py (partly to provide a reference for the second approach, but mainly because the utxocache tests are the most intricate tests, and refactoring them to use the first approach would negatively impact their readability). Lastly, interface_usdt_coinselection.py was kept unchanged because it does not use assert_equal() statements inside callback functions.

  2. DrahtBot commented at 8:33 am on June 6, 2023: contributor

    The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

    Reviews

    See the guideline for information on the review process.

    Type Reviewers
    ACK 0xB10C, willcl-ark, stickies-v

    If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

  3. DrahtBot added the label Tests on Jun 6, 2023
  4. virtu force-pushed on Jun 6, 2023
  5. 0xB10C commented at 8:58 am on June 6, 2023: contributor

    Concept ACK. Thanks for picking this up! Seeing the asserts fail in the CI logs is needed and would have helped figuring out the reason for #27380.

    (I think you meant to write assert_equal() instead of check_equal())

  6. virtu commented at 9:20 am on June 6, 2023: contributor

    (I think you meant to write assert_equal() instead of check_equal())

    You’re right. I don’t think I can change it in the PR title, but I at least fixed it in the description.

  7. fanquake renamed this:
    test: handle failed `check_equal()` assertions in bcc callback functions
    test: handle failed `assert_equal()` assertions in bcc callback functions
    on Jun 6, 2023
  8. DrahtBot added the label CI failed on Jun 6, 2023
  9. 0xB10C commented at 9:50 am on June 9, 2023: contributor

    ACK 4798c4542b44abac008bd0f12642552df35d2cc1. I code-reviewed the changes and they look good to me. The approach taken (applying the two solutions outlined in the OP on a case-by-case basis) seems OK to me.

    With #27380 in mind, I’ve checked that this commit https://github.com/0xB10C/bitcoin/commit/4e00fbb8937071fabd3a70c2cc3e6ea8e6f31a65 on top of this PR fails with AssertionError: not(min relay fee not met == min erlay fee not met) as expected in the CI logs compared to a similar change https://github.com/0xB10C/bitcoin/commit/4091d621f16b6316eef5551a56c00bf0e2c0e541 on master, which only shows AssertionError: not(1 == 0) in the CI logs.

  10. DrahtBot removed the label CI failed on Jun 9, 2023
  11. fanquake requested review from willcl-ark on Jun 12, 2023
  12. willcl-ark commented at 8:39 pm on June 12, 2023: contributor

    ACK 4798c4542b

    I was a bit unfamilar with this python library so reviewed the bcc docs and reference guide before getting started…

    Agree that these changes allow us to see errors propagated out into the test framework logs. I broke a few of the tests to ensure that this was the case.

    nit: actually we currently dump errors to stderr, not stdout, but the end result is roughly the same :)

    before:

     0 sudo test/functional/interface_usdt_mempool.py
     1[sudo] password for will:
     22023-06-12T19:58:57.016000Z TestFramework (INFO): PRNG seed is: 3746665899140184430
     32023-06-12T19:58:57.016000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test_kocthg6x
     42023-06-12T19:58:57.489000Z TestFramework (INFO): Hooking into mempool:added tracepoint...
     52023-06-12T19:58:58.266000Z TestFramework (INFO): Sending transaction...
     62023-06-12T19:58:58.275000Z TestFramework (INFO): Polling buffer...
     7Exception ignored on calling ctypes callback function: <function PerfEventArray._open_perf_buffer.<locals>.raw_cb_ at 0x7f3df4f2cb80>
     8Traceback (most recent call last):
     9  File "/usr/lib/python3/dist-packages/bcc/table.py", line 982, in raw_cb_
    10    callback(cpu, data, size)
    11  File "/home/will/src/bitcoin/test/functional/interface_usdt_mempool.py", line 153, in handle_added_event
    12    assert_equal(vsize, event.vsize + 1)
    13  File "/home/will/src/bitcoin/test/functional/test_framework/util.py", line 57, in assert_equal
    14    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
    15AssertionError: not(104 == 105)
    162023-06-12T19:58:58.276000Z TestFramework (INFO): Cleaning up mempool...
    172023-06-12T19:58:58.326000Z TestFramework (INFO): Ensuring mempool:added event was handled successfully...
    182023-06-12T19:58:58.326000Z TestFramework (ERROR): Assertion failed
    19Traceback (most recent call last):
    20  File "/home/will/src/bitcoin/test/functional/test_framework/test_framework.py", line 132, in main
    21    self.run_test()
    22  File "/home/will/src/bitcoin/test/functional/interface_usdt_mempool.py", line 340, in run_test
    23    self.added_test()
    24  File "/home/will/src/bitcoin/test/functional/interface_usdt_mempool.py", line 175, in added_test
    25    assert_equal(EXPECTED_ADDED_EVENTS, handled_added_events)
    26  File "/home/will/src/bitcoin/test/functional/test_framework/util.py", line 57, in assert_equal
    27    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
    28AssertionError: not(1 == 0)
    292023-06-12T19:58:58.379000Z TestFramework (INFO): Stopping nodes
    302023-06-12T19:58:58.582000Z TestFramework (WARNING): Not cleaning up dir /tmp/bitcoin_func_test_kocthg6x
    312023-06-12T19:58:58.582000Z TestFramework (ERROR): Test failed. Test logging available at /tmp/bitcoin_func_test_kocthg6x/test_framework.log
    322023-06-12T19:58:58.582000Z TestFramework (ERROR):
    332023-06-12T19:58:58.582000Z TestFramework (ERROR): Hint: Call /home/will/src/bitcoin/test/functional/combine_logs.py '/tmp/bitcoin_func_test_kocthg6x' to consolidate all logs
    342023-06-12T19:58:58.582000Z TestFramework (ERROR):
    352023-06-12T19:58:58.582000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
    362023-06-12T19:58:58.582000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
    372023-06-12T19:58:58.582000Z TestFramework (ERROR):
    

    After:

     0 sudo test/functional/interface_usdt_mempool.py
     12023-06-12T20:00:49.382000Z TestFramework (INFO): PRNG seed is: 7011104464737242561
     22023-06-12T20:00:49.383000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test_gwj55flk
     32023-06-12T20:00:49.808000Z TestFramework (INFO): Hooking into mempool:added tracepoint...
     42023-06-12T20:00:50.590000Z TestFramework (INFO): Sending transaction...
     52023-06-12T20:00:50.602000Z TestFramework (INFO): Polling buffer...
     62023-06-12T20:00:50.602000Z TestFramework (INFO): Cleaning up mempool...
     72023-06-12T20:00:50.607000Z TestFramework (INFO): Ensuring mempool:added event was handled successfully...
     82023-06-12T20:00:50.607000Z TestFramework (ERROR): Assertion failed
     9Traceback (most recent call last):
    10  File "/home/will/src/bitcoin/test/functional/test_framework/test_framework.py", line 132, in main
    11    self.run_test()
    12  File "/home/will/src/bitcoin/test/functional/interface_usdt_mempool.py", line 326, in run_test
    13    self.added_test()
    14  File "/home/will/src/bitcoin/test/functional/interface_usdt_mempool.py", line 171, in added_test
    15    assert_equal(event.fee, fee + 1)
    16  File "/home/will/src/bitcoin/test/functional/test_framework/util.py", line 57, in assert_equal
    17    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
    18AssertionError: not(31200 == 31201)
    192023-06-12T20:00:50.658000Z TestFramework (INFO): Stopping nodes
    202023-06-12T20:00:50.759000Z TestFramework (WARNING): Not cleaning up dir /tmp/bitcoin_func_test_gwj55flk
    212023-06-12T20:00:50.759000Z TestFramework (ERROR): Test failed. Test logging available at /tmp/bitcoin_func_test_gwj55flk/test_framework.log
    222023-06-12T20:00:50.759000Z TestFramework (ERROR):
    232023-06-12T20:00:50.759000Z TestFramework (ERROR): Hint: Call /home/will/src/bitcoin/test/functional/combine_logs.py '/tmp/bitcoin_func_test_gwj55flk' to consolidate all logs
    242023-06-12T20:00:50.759000Z TestFramework (ERROR):
    252023-06-12T20:00:50.759000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
    262023-06-12T20:00:50.759000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
    272023-06-12T20:00:50.759000Z TestFramework (ERROR):
    
  13. maflcko commented at 2:55 pm on June 13, 2023: member
    @willcl-ark If you want to “ack” a pull, and want the merge-script and bot to recognize it, you’ll have to do it in all-upper-case
  14. hebasto commented at 9:38 pm on June 13, 2023: member

    I’ve tested this PR on the old broken variant of the #23962 using TEST_RUNNER_EXTRA="--filter interface_usdt_mempool":

    • w/o this PR:
     0stdout:
     12023-06-12T14:55:58.610000Z TestFramework (INFO): PRNG seed is: 7368400044812499558
     22023-06-12T14:55:58.611000Z TestFramework (INFO): Initializing test directory /tmp/cirrus-ci-build/ci/scratch/test_runner/test_runner__🏃_20230612_145556/interface_usdt_mempool_0
     32023-06-12T14:56:00.723000Z TestFramework (INFO): Hooking into mempool:added tracepoint...
     42023-06-12T14:56:01.437000Z TestFramework (INFO): Sending transaction...
     52023-06-12T14:56:01.444000Z TestFramework (INFO): Polling buffer...
     62023-06-12T14:56:01.444000Z TestFramework (INFO): Cleaning up mempool...
     72023-06-12T14:56:01.485000Z TestFramework (INFO): Ensuring mempool:added event was handled successfully...
     82023-06-12T14:56:01.485000Z TestFramework (ERROR): Assertion failed
     9Traceback (most recent call last):
    10  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
    11    self.run_test()
    12  File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/interface_usdt_mempool.py", line 340, in run_test
    13    self.added_test()
    14  File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/interface_usdt_mempool.py", line 175, in added_test
    15    assert_equal(EXPECTED_ADDED_EVENTS, handled_added_events)
    16  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
    17    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
    18AssertionError: not(1 == 0)
    192023-06-12T14:56:01.536000Z TestFramework (INFO): Stopping nodes
    202023-06-12T14:56:01.638000Z TestFramework (WARNING): Not cleaning up dir /tmp/cirrus-ci-build/ci/scratch/test_runner/test_runner__🏃_20230612_145556/interface_usdt_mempool_0
    212023-06-12T14:56:01.638000Z TestFramework (ERROR): Test failed. Test logging available at /tmp/cirrus-ci-build/ci/scratch/test_runner/test_runner__🏃_20230612_145556/interface_usdt_mempool_0/test_framework.log
    222023-06-12T14:56:01.638000Z TestFramework (ERROR): 
    232023-06-12T14:56:01.638000Z TestFramework (ERROR): Hint: Call /tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/combine_logs.py '/tmp/cirrus-ci-build/ci/scratch/test_runner/test_runner_₿_🏃_20230612_145556/interface_usdt_mempool_0' to consolidate all logs
    242023-06-12T14:56:01.638000Z TestFramework (ERROR): 
    252023-06-12T14:56:01.638000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
    262023-06-12T14:56:01.638000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
    272023-06-12T14:56:01.638000Z TestFramework (ERROR): 
    28
    29stderr:
    30Exception ignored on calling ctypes callback function: <function PerfEventArray._open_perf_buffer.<locals>.raw_cb_ at 0x7f72a4a4d940>
    31Traceback (most recent call last):
    32  File "/usr/lib/python3/dist-packages/bcc/table.py", line 982, in raw_cb_
    33    callback(cpu, data, size)
    34  File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/interface_usdt_mempool.py", line 153, in handle_added_event
    35    assert_equal(vsize, event.vsize)
    36  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
    37    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
    38AssertionError: not(104 == 0)
    39
    40Combine the logs and print the last 99999999 lines ...
    41...
    
    • with this PR:
     0stdout:
     12023-06-13T20:46:30.245000Z TestFramework (INFO): PRNG seed is: 8934552432487963566
     22023-06-13T20:46:30.245000Z TestFramework (INFO): Initializing test directory /tmp/cirrus-ci-build/ci/scratch/test_runner/test_runner__🏃_20230613_204627/interface_usdt_mempool_0
     32023-06-13T20:46:31.761000Z TestFramework (INFO): Hooking into mempool:added tracepoint...
     42023-06-13T20:46:32.426000Z TestFramework (INFO): Sending transaction...
     52023-06-13T20:46:32.431000Z TestFramework (INFO): Polling buffer...
     62023-06-13T20:46:32.432000Z TestFramework (INFO): Cleaning up mempool...
     72023-06-13T20:46:32.437000Z TestFramework (INFO): Ensuring mempool:added event was handled successfully...
     82023-06-13T20:46:32.437000Z TestFramework (ERROR): Assertion failed
     9Traceback (most recent call last):
    10  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
    11    self.run_test()
    12  File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/interface_usdt_mempool.py", line 326, in run_test
    13    self.added_test()
    14  File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/interface_usdt_mempool.py", line 170, in added_test
    15    assert_equal(event.vsize, tx["tx"].get_vsize())
    16  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
    17    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
    18AssertionError: not(0 == 104)
    192023-06-13T20:46:32.488000Z TestFramework (INFO): Stopping nodes
    202023-06-13T20:46:32.589000Z TestFramework (WARNING): Not cleaning up dir /tmp/cirrus-ci-build/ci/scratch/test_runner/test_runner__🏃_20230613_204627/interface_usdt_mempool_0
    212023-06-13T20:46:32.589000Z TestFramework (ERROR): Test failed. Test logging available at /tmp/cirrus-ci-build/ci/scratch/test_runner/test_runner__🏃_20230613_204627/interface_usdt_mempool_0/test_framework.log
    222023-06-13T20:46:32.589000Z TestFramework (ERROR): 
    232023-06-13T20:46:32.589000Z TestFramework (ERROR): Hint: Call /tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/combine_logs.py '/tmp/cirrus-ci-build/ci/scratch/test_runner/test_runner_₿_🏃_20230613_204627/interface_usdt_mempool_0' to consolidate all logs
    242023-06-13T20:46:32.589000Z TestFramework (ERROR): 
    252023-06-13T20:46:32.590000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
    262023-06-13T20:46:32.590000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
    272023-06-13T20:46:32.590000Z TestFramework (ERROR): 
    28
    29stderr:
    30
    31Combine the logs and print the last 99999999 lines ...
    32...
    

    Note the absence of the “Exception ignored on calling ctypes callback function…” message in the stderr in the latter case in comparison to the former one.

  15. DrahtBot removed review request from willcl-ark on Jun 14, 2023
  16. Manage exceptions in bcc callback functions
    Exceptions are not propagated in ctype callback functions used by bcc.
    This means an AssertionError exception raised by check_equal() to signal
    a failed assertion is not getting caught and properly logged. Instead,
    the error is logged to stdout and execution of the handler stops.
    
    The current workaround to check whether all check_equal() assertions in
    a callback succeeded is to increment a success counter after the
    assertions (which only gets incremented if none exception is raised and
    stops execution). Then, outside the callback, the success counter can be
    used to check whether a callback executed successfully.
    
    One issue with the described workaround is that when an exception
    occurs, there is no way of telling which of the check_equal() statements
    caused the exception; moreover, there is no way of inspecting how the
    pieces of data that got compared in check_equal() differed (often
    a crucial clue when debugging what went wrong).
    
    Two fixes to this problem come to mind. The first involves having the
    callback function make event data accessible outside the callback and
    inspecting the event using check_equal() outside the callback. This
    solution still requires a counter in the callback to tell whether
    a callback was actually executed or if instead the call to
    perf_buffer_poll() timed out.
    
    The second fix entails wrapping all relevant check_equal() statements
    inside callback functions into try-catch blocks and manually logging
    AssertionErrors. While not as elegant in terms of design, this approach
    can be more pragmatic for more complex tests (e.g., ones involving
    multiple events, events of different types, or the order of events).
    
    The solution proposed here is to select the most pragmatic fix on
    a case-by-case basis: Tests in interface_usdt_net.py,
    interface_usdt_mempool.py and interface_usdt_validation.py have been
    refactored to use the first approach, while the second approach was
    chosen for interface_usdt_utxocache.py (partly to provide a reference
    for the second approach, but mainly because the utxocache tests are the
    most intricate tests, and refactoring them to use the first approach
    would negatively impact their readability). Lastly,
    interface_usdt_coinselection.py was kept unchanged because it does not
    use check_equal() statements inside callback functions.
    61f4b9b7ad
  17. in test/functional/interface_usdt_utxocache.py:198 in 4798c4542b outdated
    200+                assert_equal(0, event.index)  # prevout index
    201+                assert_equal(EARLY_BLOCK_HEIGHT, event.height)
    202+                assert_equal(50 * COIN, event.value)
    203+                assert_equal(True, event.is_coinbase)
    204+            except AssertionError as e:
    205+                self.log.error(e)
    


    achow101 commented at 8:12 pm on June 15, 2023:

    The resulting log line is not a whole lot better than nothing since it’s just the text of assertion that failed, which doesn’t include any information about where it happened.

    However self.log.execption() will log the actual exception traceback, which is useful, and it’s what the test framework does in general to log exceptions when they happen.

    0                self.log.exception("Assertion failed")
    

    virtu commented at 12:41 pm on June 19, 2023:

    Disregard my previous comment.

    That’s of course a much better approach; I replaced all occurrences of log.error() with log.exception().

  18. virtu force-pushed on Jun 19, 2023
  19. DrahtBot added the label CI failed on Jun 19, 2023
  20. 0xB10C commented at 10:28 am on June 20, 2023: contributor

    Reviewed the changes since my last review. ACK 61f4b9b7ad6e992a9dbbbb091e9b7ba9abe529ac. I’ve tested that the combined log contains both exceptions by modifying interface_usdt_utxocache.py.

    Using Logger.exception() is better. It wasn’t clear to me that the logging functions read sys.exc_info() and do log exceptions if there are any as described here.

    CI failure is unrelated.

  21. DrahtBot requested review from willcl-ark on Jun 20, 2023
  22. willcl-ark commented at 1:30 pm on June 20, 2023: contributor

    utACK 61f4b9b

    Verified that git fetch; and git diff HEAD..FETCH_HEAD only modified the logging type from my previous ack.

    This is the same change shown by 9297303d..61f4b9b7 compare (even though my local branch was at 4798c4542b and not 9297303d).

  23. DrahtBot removed review request from willcl-ark on Jun 20, 2023
  24. fanquake requested review from stickies-v on Jun 21, 2023
  25. in test/functional/interface_usdt_validation.py:1 in 61f4b9b7ad


    stickies-v commented at 6:29 pm on June 21, 2023:

    nit: you don’t really need the blocks_checked counter anymore now:

     0diff --git a/test/functional/interface_usdt_validation.py b/test/functional/interface_usdt_validation.py
     1index f9d9b525c..f32d83a50 100755
     2--- a/test/functional/interface_usdt_validation.py
     3+++ b/test/functional/interface_usdt_validation.py
     4@@ -86,7 +86,6 @@ class ValidationTracepointTest(BitcoinTestFramework):
     5                     self.duration)
     6 
     7         BLOCKS_EXPECTED = 2
     8-        blocks_checked = 0
     9         expected_blocks = dict()
    10         events = []
    11 
    12@@ -98,11 +97,10 @@ class ValidationTracepointTest(BitcoinTestFramework):
    13                   usdt_contexts=[ctx], debug=0)
    14 
    15         def handle_blockconnected(_, data, __):
    16-            nonlocal events, blocks_checked
    17+            nonlocal events
    18             event = ctypes.cast(data, ctypes.POINTER(Block)).contents
    19             self.log.info(f"handle_blockconnected(): {event}")
    20             events.append(event)
    21-            blocks_checked += 1
    22 
    23         bpf["block_connected"].open_perf_buffer(
    24             handle_blockconnected)
    25@@ -127,7 +125,7 @@ class ValidationTracepointTest(BitcoinTestFramework):
    26             # only plausibility checks
    27             assert event.duration > 0
    28             del expected_blocks[block_hash]
    29-        assert_equal(BLOCKS_EXPECTED, blocks_checked)
    30+        assert_equal(BLOCKS_EXPECTED, len(events))
    31         assert_equal(0, len(expected_blocks))
    32 
    33         bpf.cleanup()
    

    stickies-v commented at 7:08 pm on June 21, 2023:

    For all 4 methods added_test, removed_test, replaced_test and rejected_test I think it’s a bit confusing that we’re assigning all events to the same event object while simultaneously accounting for the possibility that there is more than one event. I think it would be more elegant to just store all events, and then be explicit about the expectation that we expect len(events)==1.

    In addition to being more readable (imo), this also makes debugging a bit quicker if we suddenly do end up having more than 1 event unexpectedly?

    edit: maybe more elegant removing EXPECTED_ADDED_EVENTS (etc) altogether here and just hardcoding it?

     0diff --git a/test/functional/interface_usdt_mempool.py b/test/functional/interface_usdt_mempool.py
     1index 62fdc2836..dc3520132 100755
     2--- a/test/functional/interface_usdt_mempool.py
     3+++ b/test/functional/interface_usdt_mempool.py
     4@@ -138,8 +138,7 @@ class MempoolTracepointTest(BitcoinTestFramework):
     5         the expected txid, vsize, and fee."""
     6 
     7         EXPECTED_ADDED_EVENTS = 1
     8-        handled_added_events = 0
     9-        event = None
    10+        events = []
    11 
    12         self.log.info("Hooking into mempool:added tracepoint...")
    13         node = self.nodes[0]
    14@@ -148,9 +147,7 @@ class MempoolTracepointTest(BitcoinTestFramework):
    15         bpf = BPF(text=MEMPOOL_TRACEPOINTS_PROGRAM, usdt_contexts=[ctx], debug=0)
    16 
    17         def handle_added_event(_, data, __):
    18-            nonlocal event, handled_added_events
    19-            event = bpf["added_events"].event(data)
    20-            handled_added_events += 1
    21+            events.append(bpf["added_events"].event(data))
    22 
    23         bpf["added_events"].open_perf_buffer(handle_added_event)
    24 
    25@@ -165,7 +162,8 @@ class MempoolTracepointTest(BitcoinTestFramework):
    26         self.generate(node, 1)
    27 
    28         self.log.info("Ensuring mempool:added event was handled successfully...")
    29-        assert_equal(EXPECTED_ADDED_EVENTS, handled_added_events)
    30+        assert_equal(EXPECTED_ADDED_EVENTS, len(events))
    31+        event = events[0]  # single item since EXPECTED_ADDED_EVENTS is 1
    32         assert_equal(bytes(event.hash)[::-1].hex(), tx["txid"])
    33         assert_equal(event.vsize, tx["tx"].get_vsize())
    34         assert_equal(event.fee, fee)
    
  26. in test/functional/interface_usdt_net.py:142 in 61f4b9b7ad
    138@@ -142,12 +139,13 @@ def check_p2p_message(event, inbound):
    139                     checked_outbound_version_msg += 1
    140 
    141         def handle_inbound(_, data, __):
    142+            nonlocal events
    


    stickies-v commented at 7:11 pm on June 21, 2023:
    nit: Since we’re mutating events (and not reassigning), there’s no need to declare nonlocal so I think this line can be safely removed. Or, if you prefer the explicitness of altering an object from a different scope, I’d at least stay consistent and do the same in handle_outbound?
  27. in test/functional/interface_usdt_net.py:161 in 61f4b9b7ad
    155@@ -158,12 +156,15 @@ def handle_outbound(_, data, __):
    156         bpf.perf_buffer_poll(timeout=200)
    157 
    158         self.log.info(
    159-            "check that we got both an inbound and outbound version message")
    160+            "check receipt and content of in- and outbound version messages")
    161+        for event, inbound in events:
    162+            check_p2p_message(event, inbound)
    


    stickies-v commented at 7:13 pm on June 21, 2023:

    nit: clearer naming to indicate it’s a bool

    0        for event, is_inbound in events:
    1            check_p2p_message(event, is_inbound)
    
  28. in test/functional/interface_usdt_utxocache.py:275 in 61f4b9b7ad
    276+                assert_equal(add["value"], event.value)
    277+                assert_equal(add["is_coinbase"], event.is_coinbase)
    278+            except AssertionError:
    279+                self.log.exception("Assertion failed")
    280+            else:
    281+                handle_add_succeeds += 1
    


    stickies-v commented at 7:29 pm on June 21, 2023:
    nit: this looks identical to the logic in handle_utxocache_spent so could wrap this in a compare_utxo_with_event function to deduplicate the code?
  29. stickies-v commented at 7:38 pm on June 21, 2023: contributor

    utACK 61f4b9b7a

    Can’t run this on macOS and am not familiar with BPF and bcc, but from a Python pov this looks like a reasonable change to me assuming the problem statement in OP.

    Left a few suggested improvement nits but they can all be safely ignored/followed-up, especially since we already have so many ACKs.

  30. fanquake merged this on Jun 22, 2023
  31. fanquake closed this on Jun 22, 2023

  32. sidhujag referenced this in commit 197df44985 on Jun 22, 2023
  33. fanquake commented at 9:24 am on June 23, 2023: member
    @stickies-v did you want to open a follow up?
  34. stickies-v commented at 5:04 pm on June 23, 2023: contributor

    @stickies-v did you want to open a follow up?

    Done: https://github.com/bitcoin/bitcoin/pull/27944

  35. fanquake referenced this in commit c5a63ea56f on Sep 10, 2023
  36. Frank-GER referenced this in commit a27a634c3d on Sep 19, 2023
  37. virtu deleted the branch on Apr 9, 2024

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2024-07-05 19:13 UTC

This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me