Intermittent issue in feature_proxy.py AssertionError: not(bytearray(b'node.noumenon') == b'fc00:1:2:3:4:5:6:7')

maflcko commented at 8:55 am on April 15, 2024: member

https://drahtbot.space/temp_scratch/feature_proxy_179.tar.zstd

 0 test  2024-04-13T16:24:13.025000Z TestFramework (DEBUG): Test: outgoing CJDNS connection through node 4 for address [fc00:1:2:3:4:5:6:7]:8888 
 1 node4 2024-04-13T16:24:13.089818Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:53136 
 2 node0 2024-04-13T16:24:13.090252Z [net] [net.cpp:2124] [SocketHandlerConnected] [net] socket recv error for peer=5: Connection reset by peer (104) 
 3 node0 2024-04-13T16:24:13.090319Z [net] [net.cpp:541] [CloseSocketDisconnect] [net] disconnecting peer=5 
 4 node0 2024-04-13T16:24:13.090336Z [net] [net.cpp:2124] [SocketHandlerConnected] [net] socket recv error for peer=6: Connection reset by peer (104) 
 5 node0 2024-04-13T16:24:13.090347Z [net] [net.cpp:541] [CloseSocketDisconnect] [net] disconnecting peer=6 
 6 node0 2024-04-13T16:24:13.090362Z [net] [net.cpp:2124] [SocketHandlerConnected] [net] socket recv error for peer=7: Connection reset by peer (104) 
 7 node0 2024-04-13T16:24:13.090372Z [net] [net.cpp:541] [CloseSocketDisconnect] [net] disconnecting peer=7 
 8 node0 2024-04-13T16:24:13.090387Z [net] [net.cpp:2124] [SocketHandlerConnected] [net] socket recv error for peer=8: Connection reset by peer (104) 
 9 node0 2024-04-13T16:24:13.090397Z [net] [net.cpp:541] [CloseSocketDisconnect] [net] disconnecting peer=8 
10 node0 2024-04-13T16:24:13.090538Z [net] [net_processing.cpp:1708] [FinalizeNode] [net] Cleared nodestate for peer=5 
11 node0 2024-04-13T16:24:13.090588Z [net] [net_processing.cpp:1708] [FinalizeNode] [net] Cleared nodestate for peer=6 
12 node0 2024-04-13T16:24:13.090629Z [net] [net_processing.cpp:1708] [FinalizeNode] [net] Cleared nodestate for peer=7 
13 node0 2024-04-13T16:24:13.090670Z [net] [net_processing.cpp:1708] [FinalizeNode] [net] Cleared nodestate for peer=8 
14 node3 2024-04-13T16:24:13.091019Z [net] [net.cpp:1497] [MarkBytesSent] [net] start sending v2 handshake to peer=2 
15 node3 2024-04-13T16:24:13.091068Z [net] [net.cpp:2113] [SocketHandlerConnected] [net] socket closed for peer=2 
16 node3 2024-04-13T16:24:13.091080Z [net] [net.cpp:541] [CloseSocketDisconnect] [net] disconnecting peer=2 
17 node3 2024-04-13T16:24:13.091115Z [net] [net.cpp:1497] [MarkBytesSent] [net] start sending v2 handshake to peer=3 
18 node3 2024-04-13T16:24:13.091155Z [net] [net.cpp:2113] [SocketHandlerConnected] [net] socket closed for peer=3 
19 node3 2024-04-13T16:24:13.091173Z [net] [net.cpp:541] [CloseSocketDisconnect] [net] disconnecting peer=3 
20 node3 2024-04-13T16:24:13.091208Z [net] [net.cpp:1497] [MarkBytesSent] [net] start sending v2 handshake to peer=4 
21 node3 2024-04-13T16:24:13.091226Z [net] [net.cpp:2113] [SocketHandlerConnected] [net] socket closed for peer=4 
22 node3 2024-04-13T16:24:13.091245Z [net] [net.cpp:541] [CloseSocketDisconnect] [net] disconnecting peer=4 
23 node3 2024-04-13T16:24:13.091294Z [net] [net.cpp:1891] [DisconnectNodes] [net] retrying with v1 transport protocol for peer=2 
24 node3 2024-04-13T16:24:13.091318Z [net] [net.cpp:1891] [DisconnectNodes] [net] retrying with v1 transport protocol for peer=3 
25 node3 2024-04-13T16:24:13.091340Z [net] [net.cpp:1891] [DisconnectNodes] [net] retrying with v1 transport protocol for peer=4 
26 node3 2024-04-13T16:24:13.091383Z [net] [net_processing.cpp:1708] [FinalizeNode] [net] Cleared nodestate for peer=2 
27 node3 2024-04-13T16:24:13.091447Z [net] [net_processing.cpp:1708] [FinalizeNode] [net] Cleared nodestate for peer=3 
28 node3 2024-04-13T16:24:13.091501Z [net] [net_processing.cpp:1708] [FinalizeNode] [net] Cleared nodestate for peer=4 
29 node4 2024-04-13T16:24:13.091978Z [net] [net.cpp:1497] [MarkBytesSent] [net] start sending v2 handshake to peer=2 
30 node4 2024-04-13T16:24:13.092016Z [net] [net.cpp:2113] [SocketHandlerConnected] [net] socket closed for peer=2 
31 node4 2024-04-13T16:24:13.092028Z [net] [net.cpp:541] [CloseSocketDisconnect] [net] disconnecting peer=2 
32 node4 2024-04-13T16:24:13.092063Z [net] [net.cpp:1497] [MarkBytesSent] [net] start sending v2 handshake to peer=3 
33 node4 2024-04-13T16:24:13.092082Z [net] [net.cpp:2113] [SocketHandlerConnected] [net] socket closed for peer=3 
34 node4 2024-04-13T16:24:13.092092Z [net] [net.cpp:541] [CloseSocketDisconnect] [net] disconnecting peer=3 
35 node4 2024-04-13T16:24:13.092124Z [net] [net.cpp:1497] [MarkBytesSent] [net] start sending v2 handshake to peer=4 
36 node4 2024-04-13T16:24:13.092142Z [net] [net.cpp:2113] [SocketHandlerConnected] [net] socket closed for peer=4 
37 node4 2024-04-13T16:24:13.092152Z [net] [net.cpp:541] [CloseSocketDisconnect] [net] disconnecting peer=4 
38 node4 2024-04-13T16:24:13.092200Z [net] [net.cpp:1891] [DisconnectNodes] [net] retrying with v1 transport protocol for peer=2 
39 node4 2024-04-13T16:24:13.092225Z [net] [net.cpp:1891] [DisconnectNodes] [net] retrying with v1 transport protocol for peer=3 
40 node4 2024-04-13T16:24:13.092246Z [net] [net.cpp:1891] [DisconnectNodes] [net] retrying with v1 transport protocol for peer=4 
41 node4 2024-04-13T16:24:13.092322Z [net] [net_processing.cpp:1708] [FinalizeNode] [net] Cleared nodestate for peer=2 
42 node4 2024-04-13T16:24:13.092386Z [net] [net_processing.cpp:1708] [FinalizeNode] [net] Cleared nodestate for peer=3 
43 node4 2024-04-13T16:24:13.092438Z [net] [net_processing.cpp:1708] [FinalizeNode] [net] Cleared nodestate for peer=4 
44 node4 2024-04-13T16:24:13.092791Z [httpworker.1] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=addnode user=__cookie__ 
45 node4 2024-04-13T16:24:13.092861Z [httpworker.1] [net.cpp:410] [ConnectNode] [net] trying v2 connection [fc00:1:2:3:4:5:6:7]:8888 lastseen=0.0hrs 
46 node4 2024-04-13T16:24:13.092899Z [httpworker.1] [net.cpp:481] [ConnectNode] [proxy] Using proxy: 127.0.0.1:13155 to connect to fc00:1:2:3:4:5:6:7:8888 
47 node4 2024-04-13T16:24:13.093027Z [httpworker.1] [netbase.cpp:365] [Socks5] [net] SOCKS5 connecting fc00:1:2:3:4:5:6:7 
48 node4 2024-04-13T16:24:13.093785Z [httpworker.1] [netbase.cpp:482] [Socks5] [net] SOCKS5 connected fc00:1:2:3:4:5:6:7 
49 test  2024-04-13T16:24:13.094000Z TestFramework.socks5 (DEBUG): Proxy: Socks5Command(1,3,bytearray(b'fc00:1:2:3:4:5:6:7'),8888,None,None) 
50 node4 2024-04-13T16:24:13.094187Z [httpworker.1] [net.cpp:3694] [CNode] [net] Added connection peer=5 
51 node4 2024-04-13T16:24:13.094222Z [httpworker.1] [net.cpp:3738] [PushMessage] [net] sending version (114 bytes) peer=5 
52 node4 2024-04-13T16:24:13.094253Z [httpworker.1] [net_processing.cpp:1559] [PushNodeVersion] [net] send version message: version 70016, blocks=0, txrelay=1, peer=5 
53 test  2024-04-13T16:24:13.095000Z TestFramework (ERROR): Assertion failed 
54                                   Traceback (most recent call last):
55                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
56                                       self.run_test()
57                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/feature_proxy.py", line 252, in run_test
58                                       self.node_test(self.nodes[4],
59                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/feature_proxy.py", line 202, in node_test
60                                       assert_equal(cmd.addr, b"fc00:1:2:3:4:5:6:7")
61                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/util.py", line 74, in assert_equal
62                                       raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
63                                   AssertionError: not(bytearray(b'node.noumenon') == b'fc00:1:2:3:4:5:6:7')

maflcko added the label Tests on Apr 15, 2024

maflcko added the label CI failed on Apr 15, 2024

laanwj commented at 5:45 pm on April 15, 2024: member

Looks like the two successive testcases in node_test are out of step? [fc00:1:2:3:4:5:6:7]:8888 is from the CJDNS test, node.noumenon:8333 is the name-based test after it, interfering with each other.

maflcko commented at 9:05 am on June 5, 2024: member

 0 test  2024-06-04T20:41:24.281000Z TestFramework (ERROR): Assertion failed 
 1                                   Traceback (most recent call last):
 2                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
 3                                       self.run_test()
 4                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/feature_proxy.py", line 252, in run_test
 5                                       self.node_test(self.nodes[4],
 6                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/feature_proxy.py", line 202, in node_test
 7                                       assert_equal(cmd.addr, b"fc00:1:2:3:4:5:6:7")
 8                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/util.py", line 74, in assert_equal
 9                                       raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
10                                   AssertionError: not(bytearray(b'15.61.23.23') == b'fc00:1:2:3:4:5:6:7')

maflcko commented at 10:10 am on July 25, 2024: member

I wonder if it is due to

0ci/test/00_setup_env_i686_multiprocess.sh:15:export TEST_RUNNER_EXTRA="--v2transport"

maflcko commented at 10:11 am on July 25, 2024: member

Ah yes. Well, that was quick. Steps to reproduce on the first try:

0$ while test/functional/feature_proxy.py --v2transport --valgrind  ; do true ; done 
12024-07-25T10:09:50.233000Z TestFramework (INFO): PRNG seed is: 4706088440128402104
22024-07-25T10:09:50.234000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test__c5c1wwl
32024-07-25T10:10:16.428000Z TestFramework (ERROR): Assertion failed
4
5AssertionError: not(bytearray(b'node.noumenon') == b'fc00:1:2:3:4:5:6:7')

fanquake closed this on Jul 31, 2024

fanquake referenced this in commit 33884e7e60 on Jul 31, 2024

Intermittent issue in feature_proxy.py AssertionError: not(bytearray(b’node.noumenon’) == b’fc00:1:2:3:4:5:6:7') #29871