rpc_net.py intemittent failure / assert_equal(len(getrawaddrman[table_name]), len(table

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)

maflcko added the label Tests on Nov 29, 2023

0xB10C commented at 1:14 pm on November 29, 2023: contributor

I’m taking a look at this.

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)

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).

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

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).

0xB10C commented at 2:23 pm on December 5, 2023: contributor

Improving addpeeraddress tried=true failure behavior in #28998

maflcko added the label CI failed on Jan 24, 2024

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

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.

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.

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

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).

fanquake closed this on Mar 11, 2024

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