qa: rpc_net.py failed

promag commented at 6:48 am on October 11, 2019: member

From https://travis-ci.org/bitcoin/bitcoin/jobs/596288648

 064/130 - rpc_net.py failed, Duration: 2 s
 1stdout:
 22019-10-10T21:39:05.478000Z TestFramework (INFO): Initializing test directory /home/travis/build/bitcoin/bitcoin/ci/scratch/test_runner/test_runner_₿_🏃_20191010_213817/rpc_net_66
 32019-10-10T21:39:07.122000Z TestFramework (INFO): Connect nodes both way
 42019-10-10T21:39:07.224000Z TestFramework (ERROR): Assertion failed
 5Traceback (most recent call last):
 6  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/test_framework.py", line 194, in main
 7    self.run_test()
 8  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/rpc_net.py", line 55, in run_test
 9    self._test_getnettotals()
10  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/rpc_net.py", line 81, in _test_getnettotals
11    assert_greater_than_or_equal(net_totals_after['totalbytessent'], peers_sent)
12  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/util.py", line 54, in assert_greater_than_or_equal
13    raise AssertionError("%s < %s" % (str(thing1), str(thing2)))
14AssertionError: 781 < 813
152019-10-10T21:39:07.232000Z TestFramework (INFO): Stopping nodes
162019-10-10T21:39:07.640000Z TestFramework (WARNING): Not cleaning up dir /home/travis/build/bitcoin/bitcoin/ci/scratch/test_runner/test_runner_₿_🏃_20191010_213817/rpc_net_66
172019-10-10T21:39:07.640000Z TestFramework (ERROR): Test failed. Test logging available at /home/travis/build/bitcoin/bitcoin/ci/scratch/test_runner/test_runner_₿_🏃_20191010_213817/rpc_net_66/test_framework.log
182019-10-10T21:39:07.641000Z TestFramework (ERROR): Hint: Call /home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/combine_logs.py '/home/travis/build/bitcoin/bitcoin/ci/scratch/test_runner/test_runner_₿_🏃_20191010_213817/rpc_net_66' to consolidate all logs

promag added the label Bug on Oct 11, 2019

fanquake added the label Tests on Oct 11, 2019

MarcoFalke commented at 1:31 pm on October 11, 2019: member

log:

 0test  2019-10-10T21:39:07.122000Z TestFramework (INFO): Connect nodes both way 
 1 node0 2019-10-10T21:39:07.122690Z [http] Received a POST request for / from 127.0.0.1:33816 
 2 node0 2019-10-10T21:39:07.122977Z [httpworker.2] ThreadRPCServer method=addnode user=__cookie__ 
 3 node0 2019-10-10T21:39:07.123207Z [httpworker.2] trying connection 127.0.0.1:11793 lastseen=0.0hrs 
 4 node1 2019-10-10T21:39:07.130269Z [net] Added connection peer=1 
 5 node1 2019-10-10T21:39:07.130424Z [net] connection from 127.0.0.1:43370 accepted 
 6 node0 2019-10-10T21:39:07.138011Z [httpworker.2] Added connection peer=1 
 7 node0 2019-10-10T21:39:07.138229Z [httpworker.2] sending version (114 bytes) peer=1 
 8 node0 2019-10-10T21:39:07.138524Z [httpworker.2] send version message: version 70015, blocks=0, us=[::]:0, peer=1 
 9 node1 2019-10-10T21:39:07.138986Z [msghand] received: version (114 bytes) peer=1 
10 node1 2019-10-10T21:39:07.139252Z [msghand] sending version (114 bytes) peer=1 
11 node1 2019-10-10T21:39:07.139487Z [msghand] send version message: version 70015, blocks=0, us=[::]:0, peer=1 
12 node1 2019-10-10T21:39:07.139559Z [msghand] sending verack (0 bytes) peer=1 
13 node1 2019-10-10T21:39:07.139780Z [msghand] receive version message: /Satoshi:0.19.99(testnode0)/: version 70015, blocks=0, us=[::]:0, peer=1 
14 node0 2019-10-10T21:39:07.141044Z [http] Received a POST request for / from 127.0.0.1:33816 
15 node0 2019-10-10T21:39:07.141317Z [httpworker.3] ThreadRPCServer method=getpeerinfo user=__cookie__ 
16 node0 2019-10-10T21:39:07.187028Z [msghand] received: version (114 bytes) peer=1 
17 node0 2019-10-10T21:39:07.187236Z [msghand] sending verack (0 bytes) peer=1 
18 node0 2019-10-10T21:39:07.187478Z [msghand] sending getaddr (0 bytes) peer=1 
19 node0 2019-10-10T21:39:07.187699Z [msghand] receive version message: /Satoshi:0.19.99(testnode1)/: version 70015, blocks=0, us=[::]:0, peer=1 
20 node0 2019-10-10T21:39:07.188091Z [msghand] received: verack (0 bytes) peer=1 
21 node0 2019-10-10T21:39:07.188233Z [msghand] New outbound peer connected: version: 70015, blocks=0, peer=1 (full-relay) 
22 node0 2019-10-10T21:39:07.188325Z [msghand] sending sendheaders (0 bytes) peer=1 
23 node0 2019-10-10T21:39:07.188467Z [msghand] sending sendcmpct (9 bytes) peer=1 
24 node0 2019-10-10T21:39:07.188617Z [msghand] sending sendcmpct (9 bytes) peer=1 
25 node0 2019-10-10T21:39:07.188853Z [msghand] sending ping (8 bytes) peer=1 
26 node0 2019-10-10T21:39:07.189783Z [msghand] sending feefilter (8 bytes) peer=1 
27 node1 2019-10-10T21:39:07.190922Z [msghand] received: verack (0 bytes) peer=1 
28 node1 2019-10-10T21:39:07.191069Z [msghand] sending sendheaders (0 bytes) peer=1 
29 node1 2019-10-10T21:39:07.191251Z [msghand] sending sendcmpct (9 bytes) peer=1 
30 node1 2019-10-10T21:39:07.191402Z [msghand] sending sendcmpct (9 bytes) peer=1 
31 node1 2019-10-10T21:39:07.191622Z [msghand] sending ping (8 bytes) peer=1 
32 node1 2019-10-10T21:39:07.192531Z [msghand] sending feefilter (8 bytes) peer=1 
33 node1 2019-10-10T21:39:07.193094Z [msghand] received: getaddr (0 bytes) peer=1 
34 node1 2019-10-10T21:39:07.193760Z [msghand] received: sendheaders (0 bytes) peer=1 
35 node1 2019-10-10T21:39:07.194350Z [msghand] received: sendcmpct (9 bytes) peer=1 
36 node1 2019-10-10T21:39:07.194918Z [msghand] received: sendcmpct (9 bytes) peer=1 
37 node1 2019-10-10T21:39:07.195456Z [msghand] received: ping (8 bytes) peer=1 
38 node1 2019-10-10T21:39:07.195575Z [msghand] sending pong (8 bytes) peer=1 
39 node0 2019-10-10T21:39:07.198871Z [http] Received a POST request for / from 127.0.0.1:33816 
40 node0 2019-10-10T21:39:07.199157Z [httpworker.0] ThreadRPCServer method=getpeerinfo user=__cookie__ 
41 node0 2019-10-10T21:39:07.203703Z [msghand] received: sendheaders (0 bytes) peer=1 
42 node0 2019-10-10T21:39:07.204394Z [msghand] received: sendcmpct (9 bytes) peer=1 
43 node0 2019-10-10T21:39:07.205024Z [msghand] received: sendcmpct (9 bytes) peer=1 
44 node1 2019-10-10T21:39:07.206464Z [http] Received a POST request for / from 127.0.0.1:58468 
45 node0 2019-10-10T21:39:07.207196Z [msghand] received: ping (8 bytes) peer=1 
46 node0 2019-10-10T21:39:07.207325Z [msghand] sending pong (8 bytes) peer=1 
47 node1 2019-10-10T21:39:07.207729Z [httpworker.0] ThreadRPCServer method=addnode user=__cookie__ 
48 node1 2019-10-10T21:39:07.209179Z [http] Received a POST request for / from 127.0.0.1:58468 
49 node1 2019-10-10T21:39:07.209443Z [httpworker.1] ThreadRPCServer method=getpeerinfo user=__cookie__ 
50 node1 2019-10-10T21:39:07.209605Z [msghand] received: feefilter (8 bytes) peer=1 
51 node1 2019-10-10T21:39:07.209766Z [msghand] received: feefilter of 0.00001000 BTC/kB from peer=1 
52 node0 2019-10-10T21:39:07.214720Z [http] Received a POST request for / from 127.0.0.1:33816 
53 node0 2019-10-10T21:39:07.214984Z [httpworker.1] ThreadRPCServer method=getconnectioncount user=__cookie__ 
54 node0 2019-10-10T21:39:07.216381Z [http] Received a POST request for / from 127.0.0.1:33816 
55 node0 2019-10-10T21:39:07.216658Z [httpworker.2] ThreadRPCServer method=getnettotals user=__cookie__ 
56 node1 2019-10-10T21:39:07.217115Z [msghand] received: pong (8 bytes) peer=1 
57 node0 2019-10-10T21:39:07.218314Z [http] Received a POST request for / from 127.0.0.1:33816 
58 node0 2019-10-10T21:39:07.218567Z [httpworker.3] ThreadRPCServer method=getpeerinfo user=__cookie__ 
59 node0 2019-10-10T21:39:07.223130Z [http] Received a POST request for / from 127.0.0.1:33816 
60 node0 2019-10-10T21:39:07.223390Z [httpworker.0] ThreadRPCServer method=getnettotals user=__cookie__ 
61 test  2019-10-10T21:39:07.224000Z TestFramework (ERROR): Assertion failed 
62                                   Traceback (most recent call last):
63                                     File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/test_framework.py", line 194, in main
64                                       self.run_test()
65                                     File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/rpc_net.py", line 55, in run_test
66                                       self._test_getnettotals()
67                                     File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/rpc_net.py", line 81, in _test_getnettotals
68                                       assert_greater_than_or_equal(net_totals_after['totalbytessent'], peers_sent)
69                                     File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/util.py", line 54, in assert_greater_than_or_equal
70                                       raise AssertionError("%s < %s" % (str(thing1), str(thing2)))
71                                   AssertionError: 781 < 813

MarcoFalke commented at 2:11 pm on October 11, 2019: member

This issue is that nSendBytes is incremented under the node’s lock cs_vSend. However, RecordBytesSent is not. So the rpc thread acquires the cs_vSend lock and puts the other thread on hold. While the thread is on hold, getnettotals returns the old value.

This can be fixed by making cs_vSend a “write lock” for the total bytes send in connman. See

0001-net-RecordBytesSent-under-node-cs_vSend-lock.patch.txt

MarcoFalke removed the label Tests on Oct 11, 2019

MarcoFalke added the label RPC/REST/ZMQ on Oct 11, 2019

laanwj commented at 5:30 am on October 15, 2019: member

Maybe relax the test? This seems racy at best; these are meant to be overall statistics, it doesn’t seem super important that the net totals are immediately up to date.

laanwj removed the label Bug on Oct 15, 2019

laanwj added the label Tests on Oct 15, 2019

promag closed this on Apr 26, 2020

DrahtBot locked this on Feb 15, 2022

qa: rpc_net.py failed #17107