rpc_net.py intemittent failure / assert_equal(len(getrawaddrman[table_name]), len(table_info[“entries”])) #28964

issue maflcko openend this issue on November 29, 2023
  1. maflcko commented at 8:49 am on November 29, 2023: member

    https://cirrus-ci.com/task/5884375213015040?logs=ci#L4022

     0 test  2023-11-28T23:28:31.543000Z TestFramework (ERROR): Assertion failed 
 1                                   Traceback (most recent call last):
 2                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 131, in main
 3                                       self.run_test()
 4                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/rpc_net.py", line 71, in run_test
 5                                       self.test_getrawaddrman()
 6                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/rpc_net.py", line 506, in test_getrawaddrman
 7                                       check_getrawaddrman_entries(expected)
 8                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/rpc_net.py", line 424, in check_getrawaddrman_entries
 9                                       assert_equal(len(getrawaddrman[table_name]), len(table_info["entries"]))
10                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/util.py", line 57, in assert_equal
11                                       raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
12                                   AssertionError: not(3 == 2)
  2. maflcko added the label Tests on Nov 29, 2023
  3. 0xB10C commented at 1:14 pm on November 29, 2023: contributor
    I’m taking a look at this.
  4. 0xB10C commented at 4:36 pm on November 29, 2023: contributor 
     0node1 [httpworker.2] [rpc/request.cpp:181] [parse] [rpc] ThreadRPCServer method=addpeeraddress user=__cookie__ 
 1node1 [httpworker.2] [logging/timer.h:58] [Log] [addrman] CheckAddrman: new 2, tried 1, total 3 started 
 2node1 [httpworker.2] [logging/timer.h:58] [Log] [addrman] CheckAddrman: completed (0.60ms) 
 3node1 [httpworker.2] [addrman.cpp:615] [AddSingle] [addrman] Added nrfj6inpyf73gpkyool35hcmne5zwfmse3jl3aw23vk7chdemalyaqad.onion:0 to new[238][20] 
 4node1 [httpworker.2] [addrman.cpp:687] [Add_] [addrman] Added 1 addresses (of 1) from nrfj6inpyf73gpkyool35hcmne5zwfmse3jl3aw23vk7chdemalyaqad.onion: 1 tried, 3 new 
 5node1 [httpworker.2] [logging/timer.h:58] [Log] [addrman] CheckAddrman: new 3, tried 1, total 4 started 
 6node1 [httpworker.2] [logging/timer.h:58] [Log] [addrman] CheckAddrman: completed (0.87ms) 
 7node1 [httpworker.2] [logging/timer.h:58] [Log] [addrman] CheckAddrman: new 3, tried 1, total 4 started 
 8node1 [httpworker.2] [logging/timer.h:58] [Log] [addrman] CheckAddrman: completed (0.87ms) 
 9node1 [httpworker.2] [addrman.cpp:668] [Good_] [addrman] Collision with 1.2.3.4:8333 while attempting to move nrfj6inpyf73gpkyool35hcmne5zwfmse3jl3aw23vk7chdemalyaqad.onion:0 to tried table. Collisions=1 
10node1 [httpworker.2] [logging/timer.h:58] [Log] [addrman] CheckAddrman: new 3, tried 1, total 4 started 
11test TestFramework (DEBUG): Added nrfj6inpyf73gpkyool35hcmne5zwfmse3jl3aw23vk7chdemalyaqad.onion to tried table 
12test TestFramework (DEBUG): Test that the newly added addresses appear in getrawaddrman

    seems like this didn’t work:

    https://github.com/bitcoin/bitcoin/blob/8cf2137dbeaa681f0178f1e2fd70b639e6d4f717/test/functional/rpc_net.py#L492-L504

    Did addpeeraddress return {"success": true} even if there was a collision while moving to tried?

    (still investigating)

  5. mzumsande commented at 4:57 pm on November 29, 2023: contributor

    I think that the problem is a rare collision in the tried table: node1 2023-11-28T23:28:31.447418Z (mocktime: 2023-11-28T23:28:28Z) [httpworker.2] [addrman.cpp:668] [Good_] [addrman] Collision with 1.2.3.4:8333 while attempting to move nrfj6inpyf73gpkyool35hcmne5zwfmse3jl3aw23vk7chdemalyaqad.onion:0 to tried table. Collisions=1:

    addpeeraddress reports success if the first part (adding to new) succeeded, but the second part (moving to tried) fails due to a collision (so that the addr stays in new).

  6. 0xB10C commented at 6:03 pm on November 29, 2023: contributor

    @mzumsande is there a reason why addpeeraddress should return true if it fails to put in in the table we asked it to do? Sounds like a bug to me. Or, it should at least be documented clearly.

    https://github.com/bitcoin/bitcoin/blob/7bc8c5312bf51edd3d85e1599b5d6ae32c8fd7b5/src/rpc/net.cpp#L981-L987

  7. mzumsande commented at 6:08 pm on November 29, 2023: contributor
    I don’t think there is a reason, but returning false wouldn’t be great either. It might be best could return an error code with 3 values (not added to new; added to new but failed to move to tried; everything successful).
  8. 0xB10C commented at 2:23 pm on December 5, 2023: contributor
    Improving addpeeraddress tried=true failure behavior in #28998
  9. maflcko added the label CI failed on Jan 24, 2024
  10. m3dwards commented at 10:45 am on February 28, 2024: contributor

    Same or similar issue?

     0 test  2024-02-28T10:08:07.041000Z TestFramework (ERROR): Assertion failed 
 1                                   Traceback (most recent call last):
 2                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 131, in main
 3                                       self.run_test()
 4                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/rpc_net.py", line 63, in run_test
 5                                       self.test_getpeerinfo()
 6                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/rpc_net.py", line 123, in test_getpeerinfo
 7                                       assert_equal(
 8                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/util.py", line 57, in assert_equal
 9                                       raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
10                                   AssertionError: not({'id': 2, 'network': 'not_publicly_routable', 'services': '0000000000000000', 'servicesnames': [], 'relaytxes': False, 'lastsend': 1709114886, 'lastrecv': 1709114886, 'last_transaction': 0, 'last_block': 0, 'conntime': 1709114886, 'timeoffset': 0, 'version': 0, 'subver': '', 'inbound': True, 'bip152_hb_to': False, 'bip152_hb_from': False, 'startingheight': -1, 'presynced_headers': -1, 'synced_headers': -1, 'synced_blocks': -1, 'inflight': [], 'addr_relay_enabled': False, 'addr_processed': 0, 'addr_rate_limited': 0, 'permissions': [], 'minfeefilter': Decimal('0E-8'), 'bytessent_per_msg': {}, 'bytesrecv_per_msg': {}, 'connection_type': 'inbound', 'transport_protocol_type': 'detecting', 'session_id': ''} == {'addr_processed': 0, 'addr_rate_limited': 0, 'addr_relay_enabled': False, 'bip152_hb_from': False, 'bip152_hb_to': False, 'bytesrecv_per_msg': {}, 'bytessent_per_msg': {}, 'connection_type': 'inbound', 'conntime': 1709114886, 'id': 2, 'inbound': True, 'inflight': [], 'last_block': 0, 'last_transaction': 0, 'lastrecv': 1709114886, 'lastsend': 1709114886, 'minfeefilter': Decimal('0E-8'), 'network': 'not_publicly_routable', 'permissions': [], 'presynced_headers': -1, 'relaytxes': False, 'services': '0000000000000000', 'servicesnames': [], 'session_id': 'b6552478f74e655b236cd192c85c9831b69221681ad1f971fb99a1451391b159', 'startingheight': -1, 'subver': '', 'synced_blocks': -1, 'synced_headers': -1, 'timeoffset': 0, 'transport_protocol_type': 'v2', 'version': 0})

    CI run: https://cirrus-ci.com/task/4559353030639616?logs=ci#L3823

  11. maflcko commented at 11:53 am on February 28, 2024: member

    It is in a different line, so it seems different.

    Unrelated, I think it would be useful if the assert helper would sort and pretty-print dictionaries. Otherwise it is hard to spot the difference.

  12. mzumsande commented at 2:39 pm on February 28, 2024: contributor
    yes, it’s a different issue, most likely related to #29358 - @stratospher and I are looking into it.
  13. m3dwards commented at 2:47 pm on February 28, 2024: contributor

    Gotcha.

    I have since been able to get what looks like the same issue.

     0 node1 2024-02-28T14:39:06.105966Z (mocktime: 2024-02-28T14:39:05Z) [C:\Users\Max\source\bitcoin\src\logging\timer.h:58] [Log] [addrman] CheckAddrman: completed (0.03ms)
 1 node1 2024-02-28T14:39:06.105977Z (mocktime: 2024-02-28T14:39:05Z) [C:\Users\Max\source\bitcoin\src\logging\timer.h:58] [Log] [addrman] CheckAddrman: new 3, tried 1, total 4 started
 2
 3 test  2024-02-28T14:39:06.106000Z TestFramework (ERROR): Assertion failed
 4                                   Traceback (most recent call last):
 5                                     File "C:\Users\Max\source\bitcoin\test\functional\test_framework\test_framework.py", line 131, in main
 6                                       self.run_test()
 7                                     File "C:\Users\Max\source\bitcoin/test/functional/rpc_net.py", line 72, in run_test
 8                                       self.test_getrawaddrman()
 9                                     File "C:\Users\Max\source\bitcoin/test/functional/rpc_net.py", line 512, in test_getrawaddrman
10                                       check_getrawaddrman_entries(expected)
11                                     File "C:\Users\Max\source\bitcoin/test/functional/rpc_net.py", line 430, in check_getrawaddrman_entries
12                                       assert_equal(len(getrawaddrman[table_name]), len(table_info["entries"]))
13                                     File "C:\Users\Max\source\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))
15                                   AssertionError: not(3 == 2)
16 node1 2024-02-28T14:39:06.106021Z (mocktime: 2024-02-28T14:39:05Z) [C:\Users\Max\source\bitcoin\src\logging\timer.h:58] [Log] [addrman] CheckAddrman: completed (0.04ms)
17 node1 2024-02-28T14:39:06.106033Z (mocktime: 2024-02-28T14:39:05Z) [C:\Users\Max\source\bitcoin\src\logging\timer.h:58] [Log] [addrman] CheckAddrman: new 3, tried 1, total 4 started
  14. mzumsande commented at 7:10 pm on March 11, 2024: contributor
    This can be closed after #29007 merge (#28998 could still make sense, but the CI failure cannot happen anymore).
  15. fanquake closed this on Mar 11, 2024
  16. achow101 referenced this in commit 2795e89cc5 on Mar 22, 2024
  17. bitcoin locked this on Mar 11, 2025


maflcko 0xB10C mzumsande m3dwards

Labels
Tests CI failed

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: 2025-04-03 21:12 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me