qa: rpc_net.py failed #17107

issue promag opened this issue on October 11, 2019

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

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

64/130 - rpc_net.py failed, Duration: 2 s
stdout:
2019-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
2019-10-10T21:39:07.122000Z TestFramework (INFO): Connect nodes both way
2019-10-10T21:39:07.224000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/test_framework.py", line 194, in main
    self.run_test()
  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/rpc_net.py", line 55, in run_test
    self._test_getnettotals()
  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/rpc_net.py", line 81, in _test_getnettotals
    assert_greater_than_or_equal(net_totals_after['totalbytessent'], peers_sent)
  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
    raise AssertionError("%s < %s" % (str(thing1), str(thing2)))
AssertionError: 781 < 813
2019-10-10T21:39:07.232000Z TestFramework (INFO): Stopping nodes
2019-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
2019-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
2019-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:

test  2019-10-10T21:39:07.122000Z TestFramework (INFO): Connect nodes both way 
 node0 2019-10-10T21:39:07.122690Z [http] Received a POST request for / from 127.0.0.1:33816 
 node0 2019-10-10T21:39:07.122977Z [httpworker.2] ThreadRPCServer method=addnode user=__cookie__ 
 node0 2019-10-10T21:39:07.123207Z [httpworker.2] trying connection 127.0.0.1:11793 lastseen=0.0hrs 
 node1 2019-10-10T21:39:07.130269Z [net] Added connection peer=1 
 node1 2019-10-10T21:39:07.130424Z [net] connection from 127.0.0.1:43370 accepted 
 node0 2019-10-10T21:39:07.138011Z [httpworker.2] Added connection peer=1 
 node0 2019-10-10T21:39:07.138229Z [httpworker.2] sending version (114 bytes) peer=1 
 node0 2019-10-10T21:39:07.138524Z [httpworker.2] send version message: version 70015, blocks=0, us=[::]:0, peer=1 
 node1 2019-10-10T21:39:07.138986Z [msghand] received: version (114 bytes) peer=1 
 node1 2019-10-10T21:39:07.139252Z [msghand] sending version (114 bytes) peer=1 
 node1 2019-10-10T21:39:07.139487Z [msghand] send version message: version 70015, blocks=0, us=[::]:0, peer=1 
 node1 2019-10-10T21:39:07.139559Z [msghand] sending verack (0 bytes) peer=1 
 node1 2019-10-10T21:39:07.139780Z [msghand] receive version message: /Satoshi:0.19.99(testnode0)/: version 70015, blocks=0, us=[::]:0, peer=1 
 node0 2019-10-10T21:39:07.141044Z [http] Received a POST request for / from 127.0.0.1:33816 
 node0 2019-10-10T21:39:07.141317Z [httpworker.3] ThreadRPCServer method=getpeerinfo user=__cookie__ 
 node0 2019-10-10T21:39:07.187028Z [msghand] received: version (114 bytes) peer=1 
 node0 2019-10-10T21:39:07.187236Z [msghand] sending verack (0 bytes) peer=1 
 node0 2019-10-10T21:39:07.187478Z [msghand] sending getaddr (0 bytes) peer=1 
 node0 2019-10-10T21:39:07.187699Z [msghand] receive version message: /Satoshi:0.19.99(testnode1)/: version 70015, blocks=0, us=[::]:0, peer=1 
 node0 2019-10-10T21:39:07.188091Z [msghand] received: verack (0 bytes) peer=1 
 node0 2019-10-10T21:39:07.188233Z [msghand] New outbound peer connected: version: 70015, blocks=0, peer=1 (full-relay) 
 node0 2019-10-10T21:39:07.188325Z [msghand] sending sendheaders (0 bytes) peer=1 
 node0 2019-10-10T21:39:07.188467Z [msghand] sending sendcmpct (9 bytes) peer=1 
 node0 2019-10-10T21:39:07.188617Z [msghand] sending sendcmpct (9 bytes) peer=1 
 node0 2019-10-10T21:39:07.188853Z [msghand] sending ping (8 bytes) peer=1 
 node0 2019-10-10T21:39:07.189783Z [msghand] sending feefilter (8 bytes) peer=1 
 node1 2019-10-10T21:39:07.190922Z [msghand] received: verack (0 bytes) peer=1 
 node1 2019-10-10T21:39:07.191069Z [msghand] sending sendheaders (0 bytes) peer=1 
 node1 2019-10-10T21:39:07.191251Z [msghand] sending sendcmpct (9 bytes) peer=1 
 node1 2019-10-10T21:39:07.191402Z [msghand] sending sendcmpct (9 bytes) peer=1 
 node1 2019-10-10T21:39:07.191622Z [msghand] sending ping (8 bytes) peer=1 
 node1 2019-10-10T21:39:07.192531Z [msghand] sending feefilter (8 bytes) peer=1 
 node1 2019-10-10T21:39:07.193094Z [msghand] received: getaddr (0 bytes) peer=1 
 node1 2019-10-10T21:39:07.193760Z [msghand] received: sendheaders (0 bytes) peer=1 
 node1 2019-10-10T21:39:07.194350Z [msghand] received: sendcmpct (9 bytes) peer=1 
 node1 2019-10-10T21:39:07.194918Z [msghand] received: sendcmpct (9 bytes) peer=1 
 node1 2019-10-10T21:39:07.195456Z [msghand] received: ping (8 bytes) peer=1 
 node1 2019-10-10T21:39:07.195575Z [msghand] sending pong (8 bytes) peer=1 
 node0 2019-10-10T21:39:07.198871Z [http] Received a POST request for / from 127.0.0.1:33816 
 node0 2019-10-10T21:39:07.199157Z [httpworker.0] ThreadRPCServer method=getpeerinfo user=__cookie__ 
 node0 2019-10-10T21:39:07.203703Z [msghand] received: sendheaders (0 bytes) peer=1 
 node0 2019-10-10T21:39:07.204394Z [msghand] received: sendcmpct (9 bytes) peer=1 
 node0 2019-10-10T21:39:07.205024Z [msghand] received: sendcmpct (9 bytes) peer=1 
 node1 2019-10-10T21:39:07.206464Z [http] Received a POST request for / from 127.0.0.1:58468 
 node0 2019-10-10T21:39:07.207196Z [msghand] received: ping (8 bytes) peer=1 
 node0 2019-10-10T21:39:07.207325Z [msghand] sending pong (8 bytes) peer=1 
 node1 2019-10-10T21:39:07.207729Z [httpworker.0] ThreadRPCServer method=addnode user=__cookie__ 
 node1 2019-10-10T21:39:07.209179Z [http] Received a POST request for / from 127.0.0.1:58468 
 node1 2019-10-10T21:39:07.209443Z [httpworker.1] ThreadRPCServer method=getpeerinfo user=__cookie__ 
 node1 2019-10-10T21:39:07.209605Z [msghand] received: feefilter (8 bytes) peer=1 
 node1 2019-10-10T21:39:07.209766Z [msghand] received: feefilter of 0.00001000 BTC/kB from peer=1 
 node0 2019-10-10T21:39:07.214720Z [http] Received a POST request for / from 127.0.0.1:33816 
 node0 2019-10-10T21:39:07.214984Z [httpworker.1] ThreadRPCServer method=getconnectioncount user=__cookie__ 
 node0 2019-10-10T21:39:07.216381Z [http] Received a POST request for / from 127.0.0.1:33816 
 node0 2019-10-10T21:39:07.216658Z [httpworker.2] ThreadRPCServer method=getnettotals user=__cookie__ 
 node1 2019-10-10T21:39:07.217115Z [msghand] received: pong (8 bytes) peer=1 
 node0 2019-10-10T21:39:07.218314Z [http] Received a POST request for / from 127.0.0.1:33816 
 node0 2019-10-10T21:39:07.218567Z [httpworker.3] ThreadRPCServer method=getpeerinfo user=__cookie__ 
 node0 2019-10-10T21:39:07.223130Z [http] Received a POST request for / from 127.0.0.1:33816 
 node0 2019-10-10T21:39:07.223390Z [httpworker.0] ThreadRPCServer method=getnettotals user=__cookie__ 
 test  2019-10-10T21:39:07.224000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/test_framework/test_framework.py", line 194, in main
                                       self.run_test()
                                     File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/rpc_net.py", line 55, in run_test
                                       self._test_getnettotals()
                                     File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-x86_64-unknown-linux-gnu/test/functional/rpc_net.py", line 81, in _test_getnettotals
                                       assert_greater_than_or_equal(net_totals_after['totalbytessent'], peers_sent)
                                     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
                                       raise AssertionError("%s < %s" % (str(thing1), str(thing2)))
                                   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

Contributors

Labels