[tests] Make p2p-leaktests.py more robust #11078

pull jnewbery wants to merge 1 commits into bitcoin:master from jnewbery:p2p_leaktests_robust changing 2 files +8 −2

jnewbery commented at 3:44 PM on August 17, 2017: member

There has been an example of p2p-leaktests.py failing on travis in the new service bits test (introduced in #11001 . It appeared to me that the previous p2p connections had not been fully disconnected before attempting to add new p2p connections.

I've added a sleep and restarted the NetworkThread, but I don't know whether this will fix the problem, since I'm unable to reproduce the failure locally. @MarcoFalke - not sure what you want to do here? I don't think this change could make things any worse.

jnewbery commented at 4:37 PM on August 17, 2017: member

Happened again on Travis. This seems to have become more common:

p2p-leaktests.py failed, Duration: 18 s
stdout:
2017-08-17 15:31:23.470000 TestFramework (INFO): Initializing test directory /tmp/bitcoin_test_runner_20170817_152637/p2p-leaktests_139
2017-08-17 15:31:24.008000 TestFramework.mininode (INFO): Connecting to Bitcoin Node: 127.0.0.1:12112
2017-08-17 15:31:24.009000 TestFramework.mininode (INFO): Connecting to Bitcoin Node: 127.0.0.1:12112
2017-08-17 15:31:24.010000 TestFramework.mininode (INFO): Connecting to Bitcoin Node: 127.0.0.1:12112
2017-08-17 15:31:24.011000 TestFramework.mininode (INFO): Connecting to Bitcoin Node: 127.0.0.1:12112
2017-08-17 15:31:24.012000 TestFramework.mininode (INFO): Connecting to Bitcoin Node: 127.0.0.1:12112
2017-08-17 15:31:29.034000 TestFramework (INFO): Service bits 5 and 7 are allowed after August 1st 2018
2017-08-17 15:31:29.040000 TestFramework.mininode (INFO): Connecting to Bitcoin Node: 127.0.0.1:12112
2017-08-17 15:31:29.040000 TestFramework.mininode (INFO): Connecting to Bitcoin Node: 127.0.0.1:12112
2017-08-17 15:31:39.061000 TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 146, in main
    self.run_test()
  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-i686-pc-linux-gnu/test/functional/p2p-leaktests.py", line 161, in run_test
    assert wait_until(lambda: allowed_service_bit5_node.message_count["verack"], timeout=10)
AssertionError
2017-08-17 15:31:39.062000 TestFramework (INFO): Stopping nodes
2017-08-17 15:31:41.167000 TestFramework (WARNING): Not cleaning up dir /tmp/bitcoin_test_runner_20170817_152637/p2p-leaktests_139
From /tmp/bitcoin_test_runner_20170817_152637/p2p-leaktests_139/test_framework.log :
2017-08-17 15:31:23.470000 TestFramework (INFO): Initializing test directory /tmp/bitcoin_test_runner_20170817_152637/p2p-leaktests_139
2017-08-17 15:31:23.495000 TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up
2017-08-17 15:31:24.004000 TestFramework.node0 (DEBUG): RPC successfully started
2017-08-17 15:31:24.008000 TestFramework.mininode (INFO): Connecting to Bitcoin Node: 127.0.0.1:12112
2017-08-17 15:31:24.009000 TestFramework.mininode (INFO): Connecting to Bitcoin Node: 127.0.0.1:12112
2017-08-17 15:31:24.010000 TestFramework.mininode (DEBUG): Send message to 127.0.0.1:12112: msg_version(nVersion=70014 nServices=1 nTime=Thu Aug 17 15:31:24 2017 addrTo=CAddress(nServices=1 ip=127.0.0.1 port=12112) addrFrom=CAddress(nServices=1 ip=0.0.0.0 port=0) nNonce=0x0A7734C5E0857B66 strSubVer=b'/python-mininode-tester:0.0.3/' nStartingHeight=-1 nRelay=1)
2017-08-17 15:31:24.010000 TestFramework.mininode (INFO): Connecting to Bitcoin Node: 127.0.0.1:12112
2017-08-17 15:31:24.011000 TestFramework.mininode (DEBUG): Send message to 127.0.0.1:12112: msg_version(nVersion=70014 nServices=33 nTime=Thu Aug 17 15:31:24 2017 addrTo=CAddress(nServices=1 ip=127.0.0.1 port=12112) addrFrom=CAddress(nServices=1 ip=0.0.0.0 port=0) nNonce=0x5EF40AADEC09116E strSubVer=b'/python-mininode-tester:0.0.3/' nStartingHeight=-1 nRelay=1)
2017-08-17 15:31:24.011000 TestFramework.mininode (INFO): Connecting to Bitcoin Node: 127.0.0.1:12112
2017-08-17 15:31:24.012000 TestFramework.mininode (DEBUG): Send message to 127.0.0.1:12112: msg_version(nVersion=70014 nServices=129 nTime=Thu Aug 17 15:31:24 2017 addrTo=CAddress(nServices=1 ip=127.0.0.1 port=12112) addrFrom=CAddress(nServices=1 ip=0.0.0.0 port=0) nNonce=0x02A6954A3F1500B3 strSubVer=b'/python-mininode-tester:0.0.3/' nStartingHeight=-1 nRelay=1)
2017-08-17 15:31:24.012000 TestFramework.mininode (INFO): Connecting to Bitcoin Node: 127.0.0.1:12112
2017-08-17 15:31:24.014000 TestFramework.mininode (DEBUG): Connected & Listening: 127.0.0.1:12112
2017-08-17 15:31:24.014000 TestFramework.mininode (DEBUG): Connected & Listening: 127.0.0.1:12112
2017-08-17 15:31:24.014000 TestFramework.mininode (DEBUG): Connected & Listening: 127.0.0.1:12112
2017-08-17 15:31:24.015000 TestFramework.mininode (DEBUG): Connected & Listening: 127.0.0.1:12112
2017-08-17 15:31:24.015000 TestFramework.mininode (DEBUG): Send message to 127.0.0.1:12112: msg_verack()
2017-08-17 15:31:24.015000 TestFramework.mininode (DEBUG): Send message to 127.0.0.1:12112: msg_verack()
2017-08-17 15:31:24.015000 TestFramework.mininode (DEBUG): Send message to 127.0.0.1:12112: msg_verack()
2017-08-17 15:31:24.015000 TestFramework.mininode (DEBUG): Send message to 127.0.0.1:12112: msg_verack()
2017-08-17 15:31:24.015000 TestFramework.mininode (DEBUG): Send message to 127.0.0.1:12112: msg_verack()
2017-08-17 15:31:24.015000 TestFramework.mininode (DEBUG): Send message to 127.0.0.1:12112: msg_verack()
2017-08-17 15:31:24.015000 TestFramework.mininode (DEBUG): Send message to 127.0.0.1:12112: msg_verack()
2017-08-17 15:31:24.015000 TestFramework.mininode (DEBUG): Send message to 127.0.0.1:12112: msg_verack()
2017-08-17 15:31:24.015000 TestFramework.mininode (DEBUG): Send message to 127.0.0.1:12112: msg_verack()
2017-08-17 15:31:24.016000 TestFramework.mininode (DEBUG): Send message to 127.0.0.1:12112: msg_verack()
2017-08-17 15:31:24.022000 TestFramework.mininode (DEBUG): Connected & Listening: 127.0.0.1:12112
2017-08-17 15:31:24.022000 TestFramework.mininode (DEBUG): Received message from 127.0.0.1:12112: msg_version(nVersion=70015 nServices=13 nTime=Tue Aug  1 00:00:00 2017 addrTo=CAddress(nServices=0 ip=0.0.0.0 port=0) addrFrom=CAddress(nServices=13 ip=0.0.0.0 port=0) nNonce=0x724766C0B0BB0EE3 strSubVer=b'/Satoshi:0.15.99(testnode0)/' nStartingHeight=200 nRelay=1)
2017-08-17 15:31:24.022000 TestFramework.mininode (DEBUG): Send message to 127.0.0.1:12112: msg_ping(nonce=00000000)
2017-08-17 15:31:24.023000 TestFramework.mininode (DEBUG): Send message to 127.0.0.1:12112: msg_getaddr()
2017-08-17 15:31:24.023000 TestFramework.mininode (DEBUG): Received message from 127.0.0.1:12112: msg_verack()
2017-08-17 15:31:24.023000 TestFramework.mininode (DEBUG): Closing connection to: 127.0.0.1:12112
2017-08-17 15:31:24.023000 TestFramework.mininode (DEBUG): Closing connection to: 127.0.0.1:12112
2017-08-17 15:31:24.024000 TestFramework.mininode (DEBUG): Closing connection to: 127.0.0.1:12112
2017-08-17 15:31:29.034000 TestFramework (INFO): Service bits 5 and 7 are allowed after August 1st 2018
2017-08-17 15:31:29.038000 TestFramework.mininode (DEBUG): Closing connection to: 127.0.0.1:12112
2017-08-17 15:31:29.038000 TestFramework.mininode (DEBUG): Closing connection to: 127.0.0.1:12112
2017-08-17 15:31:29.039000 TestFramework.mininode (DEBUG): Send message to 127.0.0.1:12112: msg_version(nVersion=70014 nServices=33 nTime=Thu Aug 17 15:31:29 2017 addrTo=CAddress(nServices=1 ip=127.0.0.1 port=12112) addrFrom=CAddress(nServices=1 ip=0.0.0.0 port=0) nNonce=0x25F3405E5C68A4C2 strSubVer=b'/python-mininode-tester:0.0.3/' nStartingHeight=-1 nRelay=1)
2017-08-17 15:31:29.040000 TestFramework.mininode (INFO): Connecting to Bitcoin Node: 127.0.0.1:12112
2017-08-17 15:31:29.040000 TestFramework.mininode (DEBUG): Send message to 127.0.0.1:12112: msg_version(nVersion=70014 nServices=129 nTime=Thu Aug 17 15:31:29 2017 addrTo=CAddress(nServices=1 ip=127.0.0.1 port=12112) addrFrom=CAddress(nServices=1 ip=0.0.0.0 port=0) nNonce=0x9AE2B89FE9B1DDA7 strSubVer=b'/python-mininode-tester:0.0.3/' nStartingHeight=-1 nRelay=1)
2017-08-17 15:31:29.040000 TestFramework.mininode (INFO): Connecting to Bitcoin Node: 127.0.0.1:12112
2017-08-17 15:31:39.061000 TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 146, in main
    self.run_test()
  File "/home/travis/build/bitcoin/bitcoin/build/bitcoin-i686-pc-linux-gnu/test/functional/p2p-leaktests.py", line 161, in run_test
    assert wait_until(lambda: allowed_service_bit5_node.message_count["verack"], timeout=10)
AssertionError
2017-08-17 15:31:39.062000 TestFramework (INFO): Stopping nodes
2017-08-17 15:31:39.062000 TestFramework.node0 (DEBUG): Stopping node
2017-08-17 15:31:41.167000 TestFramework.node0 (DEBUG): Node stopped
2017-08-17 15:31:41.167000 TestFramework (WARNING): Not cleaning up dir /tmp/bitcoin_test_runner_20170817_152637/p2p-leaktests_139
From /tmp/bitcoin_test_runner_20170817_152637/p2p-leaktests_139/node0/regtest/debug.log :
2017-08-17 15:31:23.498466 
2017-08-17 15:31:23.498537 Bitcoin version v0.15.99.0-eea58107
2017-08-17 15:31:23.498565 InitParameterInteraction: parameter interaction: -whitelistforcerelay=1 -> setting -whitelistrelay=1
2017-08-17 15:31:23.498605 Validating signatures for all blocks.
2017-08-17 15:31:23.498987 Using the 'standard' SHA256 implementation
2017-08-17 15:31:23.499016 Using RdRand as an additional entropy source
2017-08-17 15:31:23.613202 Default data directory /home/travis/.bitcoin
2017-08-17 15:31:23.613247 Using data directory /tmp/bitcoin_test_runner_20170817_152637/p2p-leaktests_139/node0/regtest
2017-08-17 15:31:23.613282 Using config file /tmp/bitcoin_test_runner_20170817_152637/p2p-leaktests_139/node0/bitcoin.conf
2017-08-17 15:31:23.613309 Using at most 125 automatic connections (30000 file descriptors available)
2017-08-17 15:31:23.624249 Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2017-08-17 15:31:23.636554 Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2017-08-17 15:31:23.636598 Using 0 threads for script verification
2017-08-17 15:31:23.636759 Allowing HTTP connections from: 127.0.0.0/8 ::1/128 
2017-08-17 15:31:23.636861 Binding RPC on address ::1 port 17112
2017-08-17 15:31:23.636945 libevent: getaddrinfo: address family for nodename not supported
2017-08-17 15:31:23.636971 Binding RPC on address ::1 port 17112 failed.
2017-08-17 15:31:23.636994 Binding RPC on address 127.0.0.1 port 17112
2017-08-17 15:31:23.637074 Initialized HTTP server
2017-08-17 15:31:23.637101 HTTP: creating work queue of depth 16
2017-08-17 15:31:23.637123 Starting RPC
2017-08-17 15:31:23.637151 Starting HTTP RPC server
2017-08-17 15:31:23.637179 No rpcpassword set - using random cookie authentication
2017-08-17 15:31:23.637274 Generated RPC authentication cookie /tmp/bitcoin_test_runner_20170817_152637/p2p-leaktests_139/node0/regtest/.cookie
2017-08-17 15:31:23.637304 Registering HTTP handler for / (exactmatch 1)
2017-08-17 15:31:23.637330 Registering HTTP handler for /wallet/ (exactmatch 0)
2017-08-17 15:31:23.637358 Registering HTTP handler for /rest/tx/ (exactmatch 0)
2017-08-17 15:31:23.637383 Registering HTTP handler for /rest/block/notxdetails/ (exactmatch 0)
2017-08-17 15:31:23.637409 Registering HTTP handler for /rest/block/ (exactmatch 0)
2017-08-17 15:31:23.637436 Registering HTTP handler for /rest/chaininfo (exactmatch 0)
2017-08-17 15:31:23.637462 Registering HTTP handler for /rest/mempool/info (exactmatch 0)
2017-08-17 15:31:23.637488 Registering HTTP handler for /rest/mempool/contents (exactmatch 0)
2017-08-17 15:31:23.637515 Registering HTTP handler for /rest/headers/ (exactmatch 0)
2017-08-17 15:31:23.637543 Registering HTTP handler for /rest/getutxos (exactmatch 0)
2017-08-17 15:31:23.637569 Starting HTTP server
2017-08-17 15:31:23.637596 HTTP: starting 4 worker threads
2017-08-17 15:31:23.637703 init message: Verifying wallet(s)...
2017-08-17 15:31:23.637758 Using BerkeleyDB version Berkeley DB 4.8.30: (April  9, 2010)
2017-08-17 15:31:23.637791 Using wallet wallet.dat
2017-08-17 15:31:23.637874 CDBEnv::Open: LogDir=/tmp/bitcoin_test_runner_20170817_152637/p2p-leaktests_139/node0/regtest/database ErrorFile=/tmp/bitcoin_test_runner_20170817_152637/p2p-leaktests_139/node0/regtest/db.log
2017-08-17 15:31:23.642376 Entering http event loop
2017-08-17 15:31:23.646359 scheduler thread start
2017-08-17 15:31:23.653553 Cache configuration:
2017-08-17 15:31:23.653600 * Using 2.0MiB for block index database
2017-08-17 15:31:23.653628 * Using 8.0MiB for chain state database
2017-08-17 15:31:23.653657 * Using 440.0MiB for in-memory UTXO set (plus up to 286.1MiB of unused mempool space)
2017-08-17 15:31:23.653688 init message: Loading block index...
2017-08-17 15:31:23.653872 Opening LevelDB in /tmp/bitcoin_test_runner_20170817_152637/p2p-leaktests_139/node0/regtest/blocks/index
2017-08-17 15:31:23.661810 Opened LevelDB successfully
2017-08-17 15:31:23.661862 Using obfuscation key for /tmp/bitcoin_test_runner_20170817_152637/p2p-leaktests_139/node0/regtest/blocks/index: 0000000000000000
2017-08-17 15:31:23.663439 LoadBlockIndexDB: last block file = 0
2017-08-17 15:31:23.663514 LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=201, size=47350, heights=0...200, time=2011-02-02...2014-01-02)
2017-08-17 15:31:23.663542 Checking all blk files are present...
2017-08-17 15:31:23.663614 LoadBlockIndexDB: transaction index disabled
2017-08-17 15:31:23.663655 Opening LevelDB in /tmp/bitcoin_test_runner_20170817_152637/p2p-leaktests_139/node0/regtest/chainstate
2017-08-17 15:31:23.670247 Opened LevelDB successfully
2017-08-17 15:31:23.670311 Using obfuscation key for /tmp/bitcoin_test_runner_20170817_152637/p2p-leaktests_139/node0/regtest/chainstate: 934fcde80519bf1e
2017-08-17 15:31:23.670489 Loaded best chain: hashBestChain=502446eee3f94c6081367ffa6406277ed91219a0113319ef7a430a5c3cf8bb04 height=200 date=2014-01-02 09:10:00 progress=1.000000
2017-08-17 15:31:23.670524 init message: Rewinding blocks...
2017-08-17 15:31:23.749734 Received a POST request for / from 127.0.0.1:37362
2017-08-17 15:31:23.749832 ThreadRPCServer method=getblockcount
2017-08-17 15:31:23.833622 Writing final batch of 0.00 MiB
2017-08-17 15:31:23.833729 Committed 0 changed transaction outputs (out of 0) to coin database...
2017-08-17 15:31:23.833807 init message: Verifying blocks...
2017-08-17 15:31:23.833852 Verifying last 6 blocks at level 3
2017-08-17 15:31:23.833900 [0%]...[16%]...[33%]...[50%]...[66%]...[83%]...[99%]...[DONE].
2017-08-17 15:31:23.834887 No coin database inconsistencies in last 7 blocks (7 transactions)
2017-08-17 15:31:23.834923  block index             181ms
2017-08-17 15:31:23.834979 init message: Loading wallet...
2017-08-17 15:31:23.837591 nFileVersion = 159900
2017-08-17 15:31:23.837630 Keys: 53 plaintext, 0 encrypted, 53 w/ metadata, 53 total
2017-08-17 15:31:23.848696  wallet                   13ms
2017-08-17 15:31:23.853150 keypool added 1 keys (0 internal), size=2 (1 internal)
2017-08-17 15:31:23.855151 setKeyPool.size() = 2
2017-08-17 15:31:23.855186 mapWallet.size() = 50
2017-08-17 15:31:23.855208 mapAddressBook.size() = 1
2017-08-17 15:31:23.855285 mapBlockIndex.size() = 201
2017-08-17 15:31:23.855312 nBestHeight = 200
2017-08-17 15:31:23.855371 Bound to [::]:12112
2017-08-17 15:31:23.855411 Bound to 0.0.0.0:12112
2017-08-17 15:31:23.855440 init message: Loading P2P addresses...
2017-08-17 15:31:23.855482 ERROR: DeserializeFileDB: Failed to open file /tmp/bitcoin_test_runner_20170817_152637/p2p-leaktests_139/node0/regtest/peers.dat
2017-08-17 15:31:23.855593 Invalid or missing peers.dat; recreating
2017-08-17 15:31:23.856266 Imported mempool transactions from disk: 0 successes, 0 failed, 0 expired
2017-08-17 15:31:23.858172 Flushed 0 addresses to peers.dat  3ms
2017-08-17 15:31:23.858208 init message: Loading banlist...
2017-08-17 15:31:23.858265 Loaded 0 banned node ips/subnets from banlist.dat  0ms
2017-08-17 15:31:23.858292 init message: Starting network threads...
2017-08-17 15:31:23.858415 init message: Done loading
2017-08-17 15:31:23.858498 msghand thread start
2017-08-17 15:31:23.858532 opencon thread start
2017-08-17 15:31:23.858570 addcon thread start
2017-08-17 15:31:23.858603 dnsseed thread start
2017-08-17 15:31:23.858625 Loading addresses from DNS seeds (could take a while)
2017-08-17 15:31:23.858647 0 addresses found from DNS seeds
2017-08-17 15:31:23.858667 dnsseed thread exit
2017-08-17 15:31:23.858709 net thread start
2017-08-17 15:31:24.003528 Received a POST request for / from 127.0.0.1:37366
2017-08-17 15:31:24.003631 ThreadRPCServer method=getblockcount
2017-08-17 15:31:24.004757 Received a POST request for / from 127.0.0.1:37366
2017-08-17 15:31:24.004839 ThreadRPCServer method=getblockcount
2017-08-17 15:31:24.005575 Received a POST request for / from 127.0.0.1:37366
2017-08-17 15:31:24.005663 ThreadRPCServer method=waitforblockheight
2017-08-17 15:31:24.006753 Received a POST request for / from 127.0.0.1:37366
2017-08-17 15:31:24.006827 ThreadRPCServer method=getrawmempool
2017-08-17 15:31:24.007606 Received a POST request for / from 127.0.0.1:37366
2017-08-17 15:31:24.007688 ThreadRPCServer method=setmocktime
2017-08-17 15:31:24.009070 (mocktime: 2017-08-01 00:00:00) Added connection peer=0
2017-08-17 15:31:24.009138 (mocktime: 2017-08-01 00:00:00) connection from 127.0.0.1:42184 accepted
2017-08-17 15:31:24.009984 (mocktime: 2017-08-01 00:00:00) Added connection peer=1
2017-08-17 15:31:24.010046 (mocktime: 2017-08-01 00:00:00) connection from 127.0.0.1:42186 accepted
2017-08-17 15:31:24.011167 (mocktime: 2017-08-01 00:00:00) Added connection peer=2
2017-08-17 15:31:24.011234 (mocktime: 2017-08-01 00:00:00) connection from 127.0.0.1:42188 accepted
2017-08-17 15:31:24.012231 (mocktime: 2017-08-01 00:00:00) Added connection peer=3
2017-08-17 15:31:24.012294 (mocktime: 2017-08-01 00:00:00) connection from 127.0.0.1:42190 accepted
2017-08-17 15:31:24.013304 (mocktime: 2017-08-01 00:00:00) Added connection peer=4
2017-08-17 15:31:24.013365 (mocktime: 2017-08-01 00:00:00) connection from 127.0.0.1:42192 accepted
2017-08-17 15:31:24.014683 (mocktime: 2017-08-01 00:00:00) received: version (116 bytes) peer=2
2017-08-17 15:31:24.014752 (mocktime: 2017-08-01 00:00:00) sending version (114 bytes) peer=2
2017-08-17 15:31:24.014843 (mocktime: 2017-08-01 00:00:00) send version message: version 70015, blocks=200, us=[::]:0, peer=2
2017-08-17 15:31:24.014902 (mocktime: 2017-08-01 00:00:00) sending verack (0 bytes) peer=2
2017-08-17 15:31:24.014977 (mocktime: 2017-08-01 00:00:00) receive version message: /python-mininode-tester:0.0.3/: version 70014, blocks=-1, us=127.0.0.1:12112, peer=2
2017-08-17 15:31:24.015028 (mocktime: 2017-08-01 00:00:00) added time data, samples 2, offset +1438284 (+23971 minutes)
2017-08-17 15:31:24.015079 (mocktime: 2017-08-01 00:00:00) received: version (116 bytes) peer=3
2017-08-17 15:31:24.015125 (mocktime: 2017-08-01 00:00:00) ProcessMessages(version, 116 bytes) FAILED peer=3
2017-08-17 15:31:24.015174 (mocktime: 2017-08-01 00:00:00) received: version (116 bytes) peer=4
2017-08-17 15:31:24.015219 (mocktime: 2017-08-01 00:00:00) ProcessMessages(version, 116 bytes) FAILED peer=4
2017-08-17 15:31:24.016132 (mocktime: 2017-08-01 00:00:00) disconnecting peer=3
2017-08-17 15:31:24.016195 (mocktime: 2017-08-01 00:00:00) disconnecting peer=4
2017-08-17 15:31:24.016270 (mocktime: 2017-08-01 00:00:00) received: verack (0 bytes) peer=0
2017-08-17 15:31:24.016263 (mocktime: 2017-08-01 00:00:00) Cleared nodestate for peer=3
2017-08-17 15:31:24.016358 (mocktime: 2017-08-01 00:00:00) Misbehaving: 127.0.0.1:42184 peer=0 (0 -> 1)
2017-08-17 15:31:24.016403 (mocktime: 2017-08-01 00:00:00) ProcessMessages(verack, 0 bytes) FAILED peer=0
2017-08-17 15:31:24.016455 (mocktime: 2017-08-01 00:00:00) received: verack (0 bytes) peer=0
2017-08-17 15:31:24.016498 (mocktime: 2017-08-01 00:00:00) Misbehaving: 127.0.0.1:42184 peer=0 (1 -> 2)
2017-08-17 15:31:24.016539 (mocktime: 2017-08-01 00:00:00) ProcessMessages(verack, 0 bytes) FAILED peer=0
2017-08-17 15:31:24.016587 (mocktime: 2017-08-01 00:00:00) received: verack (0 bytes) peer=0
2017-08-17 15:31:24.016630 (mocktime: 2017-08-01 00:00:00) Misbehaving: 127.0.0.1:42184 peer=0 (2 -> 3)
2017-08-17 15:31:24.016671 (mocktime: 2017-08-01 00:00:00) ProcessMessages(verack, 0 bytes) FAILED peer=0
2017-08-17 15:31:24.016719 (mocktime: 2017-08-01 00:00:00) received: verack (0 bytes) peer=0
2017-08-17 15:31:24.016761 (mocktime: 2017-08-01 00:00:00) Misbehaving: 127.0.0.1:42184 peer=0 (3 -> 4)
2017-08-17 15:31:24.016801 (mocktime: 2017-08-01 00:00:00) ProcessMessages(verack, 0 bytes) FAILED peer=0
2017-08-17 15:31:24.016850 (mocktime: 2017-08-01 00:00:00) received: verack (0 bytes) peer=0
2017-08-17 15:31:24.016903 (mocktime: 2017-08-01 00:00:00) Misbehaving: 127.0.0.1:42184 peer=0 (4 -> 5)
2017-08-17 15:31:24.016943 (mocktime: 2017-08-01 00:00:00) ProcessMessages(verack, 0 bytes) FAILED peer=0
2017-08-17 15:31:24.016991 (mocktime: 2017-08-01 00:00:00) received: verack (0 bytes) peer=0
2017-08-17 15:31:24.017033 (mocktime: 2017-08-01 00:00:00) Misbehaving: 127.0.0.1:42184 peer=0 (5 -> 6)
2017-08-17 15:31:24.017081 (mocktime: 2017-08-01 00:00:00) ProcessMessages(verack, 0 bytes) FAILED peer=0
2017-08-17 15:31:24.017129 (mocktime: 2017-08-01 00:00:00) received: verack (0 bytes) peer=0
2017-08-17 15:31:24.017171 (mocktime: 2017-08-01 00:00:00) Misbehaving: 127.0.0.1:42184 peer=0 (6 -> 7)
2017-08-17 15:31:24.017212 (mocktime: 2017-08-01 00:00:00) ProcessMessages(verack, 0 bytes) FAILED peer=0
2017-08-17 15:31:24.017259 (mocktime: 2017-08-01 00:00:00) received: verack (0 bytes) peer=0
2017-08-17 15:31:24.017302 (mocktime: 2017-08-01 00:00:00) Misbehaving: 127.0.0.1:42184 peer=0 (7 -> 8)
2017-08-17 15:31:24.017343 (mocktime: 2017-08-01 00:00:00) ProcessMessages(verack, 0 bytes) FAILED peer=0
2017-08-17 15:31:24.017391 (mocktime: 2017-08-01 00:00:00) received: verack (0 bytes) peer=0
2017-08-17 15:31:24.017433 (mocktime: 2017-08-01 00:00:00) Misbehaving: 127.0.0.1:42184 peer=0 (8 -> 9)
2017-08-17 15:31:24.017473 (mocktime: 2017-08-01 00:00:00) ProcessMessages(verack, 0 bytes) FAILED peer=0
2017-08-17 15:31:24.017520 (mocktime: 2017-08-01 00:00:00) received: verack (0 bytes) peer=0
2017-08-17 15:31:24.017562 (mocktime: 2017-08-01 00:00:00) Misbehaving: 127.0.0.1:42184 peer=0 (9 -> 10) BAN THRESHOLD EXCEEDED
2017-08-17 15:31:24.017603 (mocktime: 2017-08-01 00:00:00) ProcessMessages(verack, 0 bytes) FAILED peer=0
2017-08-17 15:31:24.017650 (mocktime: 2017-08-01 00:00:00) Warning: not banning local peer 127.0.0.1:42184!
2017-08-17 15:31:24.017744 (mocktime: 2017-08-01 00:00:00) Cleared nodestate for peer=4
2017-08-17 15:31:24.023591 (mocktime: 2017-08-01 00:00:00) disconnecting peer=0
2017-08-17 15:31:24.023671 (mocktime: 2017-08-01 00:00:00) Cleared nodestate for peer=0
2017-08-17 15:31:24.023780 (mocktime: 2017-08-01 00:00:00) received: ping (8 bytes) peer=2
2017-08-17 15:31:24.023835 (mocktime: 2017-08-01 00:00:00) Misbehaving: 127.0.0.1:42188 peer=2 (0 -> 1)
2017-08-17 15:31:24.023881 (mocktime: 2017-08-01 00:00:00) ProcessMessages(ping, 8 bytes) FAILED peer=2
2017-08-17 15:31:24.023934 (mocktime: 2017-08-01 00:00:00) received: getaddr (0 bytes) peer=2
2017-08-17 15:31:24.023980 (mocktime: 2017-08-01 00:00:00) Misbehaving: 127.0.0.1:42188 peer=2 (1 -> 2)
2017-08-17 15:31:24.024024 (mocktime: 2017-08-01 00:00:00) ProcessMessages(getaddr, 0 bytes) FAILED peer=2
2017-08-17 15:31:24.024556 (mocktime: 2017-08-01 00:00:00) Received a POST request for / from 127.0.0.1:37366
2017-08-17 15:31:24.024661 (mocktime: 2017-08-01 00:00:00) ThreadRPCServer method=generate
2017-08-17 15:31:24.024769 (mocktime: 2017-08-01 00:00:00) keypool reserve 3
2017-08-17 15:31:24.024853 (mocktime: 2017-08-01 00:00:00) CreateNewBlock(): total size: 227 block weight: 908 txs: 0 fees: 0 sigops 400
2017-08-17 15:31:24.024938 (mocktime: 2017-08-01 00:00:00)     - Sanity checks: 0.01ms [0.00s]
2017-08-17 15:31:24.025000 (mocktime: 2017-08-01 00:00:00)     - Fork checks: 0.07ms [0.00s]
2017-08-17 15:31:24.025054 (mocktime: 2017-08-01 00:00:00)       - Connect 1 transactions: 0.05ms (0.052ms/tx, 0.000ms/txin) [0.00s]
2017-08-17 15:31:24.025097 (mocktime: 2017-08-01 00:00:00)     - Verify 0 txins: 0.10ms (0.000ms/txin) [0.00s]
2017-08-17 15:31:24.025139 (mocktime: 2017-08-01 00:00:00) CreateNewBlock() packages: 0.01ms (0 packages, 0 updated descendants), validity: 0.30ms (total 0.32ms)
2017-08-17 15:31:24.025533 (mocktime: 2017-08-01 00:00:00)   - Load block from disk: 0.00ms [0.00s]
2017-08-17 15:31:24.025595 (mocktime: 2017-08-01 00:00:00)     - Sanity checks: 0.00ms [0.00s]
2017-08-17 15:31:24.025650 (mocktime: 2017-08-01 00:00:00)     - Fork checks: 0.06ms [0.00s]
2017-08-17 15:31:24.025704 (mocktime: 2017-08-01 00:00:00)       - Connect 1 transactions: 0.05ms (0.052ms/tx, 0.000ms/txin) [0.00s]
2017-08-17 15:31:24.025747 (mocktime: 2017-08-01 00:00:00)     - Verify 0 txins: 0.10ms (0.000ms/txin) [0.00s]
2017-08-17 15:31:24.025829 (mocktime: 2017-08-01 00:00:00)     - Index writing: 0.08ms [0.00s]
2017-08-17 15:31:24.025879 (mocktime: 2017-08-01 00:00:00)     - Callbacks: 0.04ms [0.00s]
2017-08-17 15:31:24.025927 (mocktime: 2017-08-01 00:00:00)   - Connect total: 0.40ms [0.00s]
2017-08-17 15:31:24.025976 (mocktime: 2017-08-01 00:00:00)   - Flush: 0.05ms [0.00s]
2017-08-17 15:31:24.026019 (mocktime: 2017-08-01 00:00:00)   - Writing chainstate: 0.04ms [0.00s]
2017-08-17 15:31:24.026251 (mocktime: 2017-08-01 00:00:00) Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 0 from current
2017-08-17 15:31:24.026296 (mocktime: 2017-08-01 00:00:00) Leaving InitialBlockDownload (latching to false)
2017-08-17 15:31:24.026457 (mocktime: 2017-08-01 00:00:00) UpdateTip: new best=783b8eae60318aef016b17226415a3fa139b739a3001f304d40ce834f9650242 height=201 version=0x30000003 log2_work=8.6582115 tx=202 date='2017-08-01 00:00:00' progress=1.000000 cache=0.0MiB(1txo)
2017-08-17 15:31:24.026504 (mocktime: 2017-08-01 00:00:00)   - Connect postprocess: 0.49ms [0.00s]
2017-08-17 15:31:24.026544 (mocktime: 2017-08-01 00:00:00) - Connect block: 0.98ms [0.00s]
2017-08-17 15:31:24.026590 (mocktime: 2017-08-01 00:00:00) Checking mempool with 0 transactions and 0 inputs
2017-08-17 15:31:24.026772 (mocktime: 2017-08-01 00:00:00) AddToWallet c243da501a4eb84ff7ebf3e6ca2244ee3a97bbcf65ff409e276f91259c59c077  new
2017-08-17 15:31:24.027074 (mocktime: 2017-08-01 00:00:00) keypool keep 3
2017-08-17 15:31:29.035062 (mocktime: 2017-08-01 00:00:00) Received a POST request for / from 127.0.0.1:37366
2017-08-17 15:31:29.035170 (mocktime: 2017-08-01 00:00:00) ThreadRPCServer method=setmocktime
2017-08-17 15:31:29.038882 (mocktime: 2018-08-02 00:00:00) socket closed
2017-08-17 15:31:29.038942 (mocktime: 2018-08-02 00:00:00) disconnecting peer=1
2017-08-17 15:31:29.039021 (mocktime: 2018-08-02 00:00:00) socket closed
2017-08-17 15:31:29.039065 (mocktime: 2018-08-02 00:00:00) disconnecting peer=2
2017-08-17 15:31:29.039132 (mocktime: 2018-08-02 00:00:00) Cleared nodestate for peer=1
2017-08-17 15:31:29.039221 (mocktime: 2018-08-02 00:00:00) Cleared nodestate for peer=2
2017-08-17 15:31:29.041272 (mocktime: 2018-08-02 00:00:00) Added connection peer=5
2017-08-17 15:31:29.041348 (mocktime: 2018-08-02 00:00:00) connection from 127.0.0.1:42210 accepted
2017-08-17 15:31:29.042027 (mocktime: 2018-08-02 00:00:00) Added connection peer=6
2017-08-17 15:31:29.042082 (mocktime: 2018-08-02 00:00:00) connection from 127.0.0.1:42212 accepted
2017-08-17 15:31:29.359388 (mocktime: 2018-08-02 00:00:00) Adding fixed seed nodes as DNS doesn't seem to be available.
2017-08-17 15:31:29.359497 (mocktime: 2018-08-02 00:00:00) Flushing wallet.dat
2017-08-17 15:31:29.361800 (mocktime: 2018-08-02 00:00:00) Flushed wallet.dat 2ms
2017-08-17 15:31:39.062844 (mocktime: 2018-08-02 00:00:00) Received a POST request for / from 127.0.0.1:37366
2017-08-17 15:31:39.062954 (mocktime: 2018-08-02 00:00:00) ThreadRPCServer method=stop
2017-08-17 15:31:39.069276 (mocktime: 2018-08-02 00:00:00) Interrupting HTTP server
2017-08-17 15:31:39.069350 (mocktime: 2018-08-02 00:00:00) Interrupting HTTP RPC server
2017-08-17 15:31:39.069392 (mocktime: 2018-08-02 00:00:00) Interrupting RPC
2017-08-17 15:31:39.069461 (mocktime: 2018-08-02 00:00:00) addcon thread exit
2017-08-17 15:31:39.069518 (mocktime: 2018-08-02 00:00:00) scheduler thread interrupt
2017-08-17 15:31:39.069527 (mocktime: 2018-08-02 00:00:00) opencon thread exit
2017-08-17 15:31:39.069683 (mocktime: 2018-08-02 00:00:00) Shutdown: In progress...
2017-08-17 15:31:39.069729 (mocktime: 2018-08-02 00:00:00) Stopping HTTP RPC server
2017-08-17 15:31:39.069753 (mocktime: 2018-08-02 00:00:00) Unregistering HTTP handler for / (exactmatch 1)
2017-08-17 15:31:39.069778 (mocktime: 2018-08-02 00:00:00) Unregistering HTTP handler for /rest/tx/ (exactmatch 0)
2017-08-17 15:31:39.069801 (mocktime: 2018-08-02 00:00:00) Unregistering HTTP handler for /rest/block/notxdetails/ (exactmatch 0)
2017-08-17 15:31:39.069836 (mocktime: 2018-08-02 00:00:00) Unregistering HTTP handler for /rest/block/ (exactmatch 0)
2017-08-17 15:31:39.069859 (mocktime: 2018-08-02 00:00:00) Unregistering HTTP handler for /rest/chaininfo (exactmatch 0)
2017-08-17 15:31:39.069881 (mocktime: 2018-08-02 00:00:00) Unregistering HTTP handler for /rest/mempool/info (exactmatch 0)
2017-08-17 15:31:39.069911 (mocktime: 2018-08-02 00:00:00) Unregistering HTTP handler for /rest/mempool/contents (exactmatch 0)
2017-08-17 15:31:39.069933 (mocktime: 2018-08-02 00:00:00) Unregistering HTTP handler for /rest/headers/ (exactmatch 0)
2017-08-17 15:31:39.069955 (mocktime: 2018-08-02 00:00:00) Unregistering HTTP handler for /rest/getutxos (exactmatch 0)
2017-08-17 15:31:39.069976 (mocktime: 2018-08-02 00:00:00) Stopping RPC
2017-08-17 15:31:39.070039 (mocktime: 2018-08-02 00:00:00) RPC stopped.
2017-08-17 15:31:39.070063 (mocktime: 2018-08-02 00:00:00) Stopping HTTP server
2017-08-17 15:31:39.070084 (mocktime: 2018-08-02 00:00:00) Waiting for HTTP worker threads to exit
2017-08-17 15:31:39.070107 (mocktime: 2018-08-02 00:00:00) Waiting for HTTP event thread to exit
2017-08-17 15:31:39.110841 (mocktime: 2018-08-02 00:00:00) net thread exit
2017-08-17 15:31:39.144855 (mocktime: 2018-08-02 00:00:00) msghand thread exit
2017-08-17 15:31:41.070229 (mocktime: 2018-08-02 00:00:00) HTTP event loop did not exit within allotted time, sending loopbreak
2017-08-17 15:31:41.070357 (mocktime: 2018-08-02 00:00:00) Exited http event loop
2017-08-17 15:31:41.070529 (mocktime: 2018-08-02 00:00:00) Stopped HTTP server
2017-08-17 15:31:41.070564 (mocktime: 2018-08-02 00:00:00) CDBEnv::Flush: Flush(false)
2017-08-17 15:31:41.070589 (mocktime: 2018-08-02 00:00:00) CDBEnv::Flush: Flush(false) took               0ms
2017-08-17 15:31:41.073804 (mocktime: 2018-08-02 00:00:00) Flushed 0 addresses to peers.dat  3ms
2017-08-17 15:31:41.073841 (mocktime: 2018-08-02 00:00:00) disconnecting peer=5
2017-08-17 15:31:41.073883 (mocktime: 2018-08-02 00:00:00) disconnecting peer=6
2017-08-17 15:31:41.073930 (mocktime: 2018-08-02 00:00:00) Cleared nodestate for peer=5
2017-08-17 15:31:41.073994 (mocktime: 2018-08-02 00:00:00) Cleared nodestate for peer=6
2017-08-17 15:31:41.076035 (mocktime: 2018-08-02 00:00:00) Dumped mempool: 2e-06s to copy, 0.001944s to dump
2017-08-17 15:31:41.076075 (mocktime: 2018-08-02 00:00:00) Recorded 0 unconfirmed txs from mempool in 1e-06s
2017-08-17 15:31:41.080653 (mocktime: 2018-08-02 00:00:00) Writing final batch of 0.00 MiB
2017-08-17 15:31:41.080700 (mocktime: 2018-08-02 00:00:00) Committed 1 changed transaction outputs (out of 1) to coin database...
2017-08-17 15:31:41.084896 (mocktime: 2018-08-02 00:00:00) Writing final batch of 0.00 MiB
2017-08-17 15:31:41.084941 (mocktime: 2018-08-02 00:00:00) Committed 0 changed transaction outputs (out of 0) to coin database...
2017-08-17 15:31:41.086445 (mocktime: 2018-08-02 00:00:00) CDBEnv::Flush: Flush(true)
2017-08-17 15:31:41.086486 (mocktime: 2018-08-02 00:00:00) CDBEnv::Flush: Flushing wallet.dat (refcount = 0)...
2017-08-17 15:31:41.086580 (mocktime: 2018-08-02 00:00:00) CDBEnv::Flush: wallet.dat checkpoint
2017-08-17 15:31:41.087177 (mocktime: 2018-08-02 00:00:00) CDBEnv::Flush: wallet.dat detach
2017-08-17 15:31:41.088436 (mocktime: 2018-08-02 00:00:00) CDBEnv::Flush: wallet.dat closed
2017-08-17 15:31:41.088470 (mocktime: 2018-08-02 00:00:00) CDBEnv::Flush: Flush(true) took               2ms
2017-08-17 15:31:41.092387 (mocktime: 2018-08-02 00:00:00) Shutdown: done
2017-08-17 15:31:41.168000 TestFramework (ERROR): Test failed. Test logging available at /tmp/bitcoin_test_runner_20170817_152637/p2p-leaktests_139/test_framework.log

laanwj added the label Tests on Aug 17, 2017

in test/functional/p2p-leaktests.py:157 in fc70754e79 outdated

 150 | @@ -150,6 +151,9 @@ def run_test(self):
 151 |          self.log.info("Service bits 5 and 7 are allowed after August 1st 2018")
 152 |          self.nodes[0].setmocktime(1533168000)  # August 2nd 2018
 153 |  
 154 | +        # change in mocktime causes bitcoind to disconnect P2P connections. Sleep for a second to allow that to complete before attempting to reconnect
 155 | +        time.sleep(1)

laanwj commented at 8:49 PM on August 17, 2017:

Making things more robust by adding sleeps w/out checks is kind of meh (as things can be terribly laggy). Can it check this precondition somehow and sleep longer if necessary?

jnewbery force-pushed on Aug 18, 2017
jnewbery commented at 3:50 PM on August 18, 2017: member
Making things more robust by adding sleeps w/out checks is kind of meh (as things can be terribly laggy). Can it check this precondition somehow and sleep longer if necessary?

yes, you're right - it's meh, and in this case it was a red herring. I've managed to work out what was going wrong. When the NodeConns are disconnected here:
```
[conn.disconnect_node() for conn in connections]
```
in a reasonably fast environment, the test will continue and add the new NodeConns:
```
allowed_service_bit5_node.add_connection(connections[5])
```
before the old NodeConns are fully disconnected.

In a slower environment (Travis), the NodeConnss could be fully disconnected before we add the new ones. If that happens, the test_framework's NetworkThread exits, so we won't be able to send/receive messages over the p2p connection.

So it's kind of the opposite of what I thought. The solution is to restart the thread with NetworkThread().start() after the new NodeConns are started.

I've also added a wait_until() to make sure the previous nodes have stopped to improve that part of the test, and logging for when the network thread closes.
jnewbery force-pushed on Aug 18, 2017
[tests] Make p2p-leaktests.py more robust 0063d2c3dc

in test/functional/p2p-leaktests.py:165 in fb568240df outdated

 159 | @@ -158,6 +160,8 @@ def run_test(self):
 160 |          allowed_service_bit5_node.add_connection(connections[5])
 161 |          allowed_service_bit7_node.add_connection(connections[6])
 162 |  
 163 | +        NetworkThread().start()  # Network thread stopped when all previous NodeConnCBs disconnected. Restart it
 164 | +
 165 |          assert wait_until(lambda: allowed_service_bit5_node.message_count["verack"], timeout=10)

TheBlueMatt commented at 12:01 AM on August 21, 2017:

I've seen this test fail locally with high -j on a system with slow I/O at this assert, I assume this patch will help, though I was unable to reproduce reliably to test :(.

jnewbery force-pushed on Aug 24, 2017
jnewbery commented at 2:43 PM on September 13, 2017: member

This is still causing occasional failures on Travis. @MarcoFalke - any chance of review/merge?
MarcoFalke commented at 4:52 PM on September 13, 2017: member

@jnewbery Thanks for the ping. I ignored the pull because I assumed it still had the ugly sleep in it.
MarcoFalke commented at 4:55 PM on September 13, 2017: member

utACK 0063d2c3d
MarcoFalke merged this on Sep 13, 2017
MarcoFalke closed this on Sep 13, 2017
MarcoFalke referenced this in commit 42973f8344 on Sep 13, 2017
jnewbery deleted the branch on Sep 13, 2017
MarcoFalke referenced this in commit fff50b6a39 on Oct 3, 2017
MarcoFalke referenced this in commit f1ced0d776 on Oct 3, 2017
attilaaf referenced this in commit 4ffc9140a8 on May 25, 2019
PastaPastaPasta referenced this in commit 3fec5ef17c on Sep 24, 2019
PastaPastaPasta referenced this in commit 28f9b8b67c on Dec 21, 2019
PastaPastaPasta referenced this in commit d5fcfed522 on Jan 2, 2020
PastaPastaPasta referenced this in commit bc7b3574e5 on Jan 4, 2020
PastaPastaPasta referenced this in commit a6eb67bb90 on Jan 4, 2020
PastaPastaPasta referenced this in commit 0a65bf8cf3 on Jan 10, 2020
PastaPastaPasta referenced this in commit 14feeb8100 on Jan 10, 2020
PastaPastaPasta referenced this in commit 00167dea54 on Jan 10, 2020
PastaPastaPasta referenced this in commit b7837f02e0 on Jan 12, 2020
ckti referenced this in commit ddbd830d5a on Mar 28, 2021
gades referenced this in commit 9781144586 on Jun 30, 2021
DrahtBot locked this on Sep 8, 2021

Contributors

Labels

Linked (view graph)

#11001 [tests] Test disconnecting unsupported service bits logic.