txn_doublespend.py and segwit.py failing on Travis #8532

laanwj commented at 12:09 PM on August 17, 2016: member

These seem to fail quite consistently on Travis

txn_doublespend.py --mineblock:
Initializing test directory /tmp/test8j7bh6g3/33
start_node: bitcoind started, waiting for RPC to come up
start_node: RPC succesfully started
start_node: bitcoind started, waiting for RPC to come up
start_node: RPC succesfully started
start_node: bitcoind started, waiting for RPC to come up
start_node: RPC succesfully started
start_node: bitcoind started, waiting for RPC to come up
start_node: RPC succesfully started
JSONRPC error: Invalid or non-wallet transaction id
Stopping nodes
Not cleaning up dir /tmp/test8j7bh6g3/33
Failed
stderr:
   File "/home/travis/build/bitcoin/bitcoin/qa/rpc-tests/test_framework/test_framework.py", line 150, in main
    self.run_test()
  File "/home/travis/build/bitcoin/bitcoin/build/../qa/rpc-tests/txn_doublespend.py", line 112, in run_test
    assert_equal(self.nodes[0].gettransaction(doublespend_txid)["confirmations"], 2)
  File "/home/travis/build/bitcoin/bitcoin/qa/rpc-tests/test_framework/coverage.py", line 49, in __call__
    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
  File "/home/travis/build/bitcoin/bitcoin/qa/rpc-tests/test_framework/authproxy.py", line 146, in __call__
    raise JSONRPCException(response['error'])
Pass: False, Duration: 4 s
......
segwit.py:
Initializing test directory /tmp/test7aabs7g2/31
start_node: bitcoind started, waiting for RPC to come up
start_node: RPC succesfully started
start_node: bitcoind started, waiting for RPC to come up
start_node: RPC succesfully started
start_node: bitcoind started, waiting for RPC to come up
start_node: RPC succesfully started
Verify sigops are counted in GBT with pre-BIP141 rules before the fork
Assertion failed: 699.98600000 != 999.980
Stopping nodes
Not cleaning up dir /tmp/test7aabs7g2/31
Failed
stderr:
   File "/home/travis/build/bitcoin/bitcoin/qa/rpc-tests/test_framework/test_framework.py", line 150, in main
    self.run_test()
  File "/home/travis/build/bitcoin/bitcoin/build/../qa/rpc-tests/segwit.py", line 168, in run_test
    assert_equal(self.nodes[2].getbalance(), 20*Decimal("49.999"))
  File "/home/travis/build/bitcoin/bitcoin/qa/rpc-tests/test_framework/util.py", line 504, in assert_equal
    raise AssertionError("%s != %s"%(str(thing1),str(thing2)))
Pass: False, Duration: 3 s

laanwj added the label Tests on Aug 17, 2016

laanwj commented at 12:11 PM on August 17, 2016: member

Seems to have started with #8482's merge.

sipa commented at 12:14 PM on August 17, 2016: member

I think I saw Verify sigops are counted in GBT with pre-BIP141 rules before the fork mentioned elsewhere before.

laanwj commented at 12:15 PM on August 17, 2016: member

Yeah, as usual I can't reproduce it locally, so bisection is out of the question...

sipa commented at 12:16 PM on August 17, 2016: member

Yes, I've tried reproducing as well, but failed.

laanwj commented at 12:58 PM on August 17, 2016: member

And I just got a mail from travis that after the most recent commit, it regards the state as "fixed." https://travis-ci.org/bitcoin/bitcoin/builds/152939796

Hmm. So it is an intermittent problem but it did happen about three times in a row, so at worst a very frequent one.

MarcoFalke commented at 7:32 PM on August 17, 2016: member

I think you are just lucky to see current HEAD of master passing. The failures are still appearing more or less consistently in builds of pull requests.

theuni commented at 1:49 AM on August 18, 2016: member

I managed to reproduce the segwit failure locally:

stderr:
   File "/Users/cory/dev/bitcoin/qa/rpc-tests/test_framework/test_framework.py", line 150, in main
    self.run_test()
  File "/Users/cory/dev/bitcoin/qa/rpc-tests/segwit.py", line 167, in run_test
    assert_equal(self.nodes[1].getbalance(), 20*Decimal("49.999"))
  File "/Users/cory/dev/bitcoin/qa/rpc-tests/test_framework/util.py", line 504, in assert_equal
    raise AssertionError("%s != %s"%(str(thing1),str(thing2)))

Pass: False, Duration: 26 s

relevant part of log (node1):

2016-08-18 01:23:30.944692 UpdateTip: new best=50a069be5d602016fcf691488dfbce82564fa104f19c2adc144125f4fd5c6385 height=163 version=0x30000003 log2_work=8.357552 tx=225 date='2016-08-18 01:23:47' progress=1.000000 cache=0.0MiB(224tx)
2016-08-18 01:23:30.945027   - Connect postprocess: 0.72ms [0.26s]
2016-08-18 01:23:30.945061 - Connect block: 22.16ms [2.07s]
2016-08-18 01:23:30.945088 Checking mempool with 0 transactions and 0 inputs
2016-08-18 01:23:30.945236 AddToWallet f36c4a847210afbc4568f8ba477d5c277fff64252f64063ea06efb9367504dda  new
2016-08-18 01:23:30.945352 AddToWallet 9d42a8fe6c4a79f81a2eb6c970224c4265abb56435d3ea5fffcbbcd48c045904  new
2016-08-18 01:23:30.945446 AddToWallet 5267dfd8b32c88615bcd07750dfee5516fe56aef7d7d133b90bc8f9ac14a421b  new
2016-08-18 01:23:30.945552 AddToWallet 82cdbd1259c1cb9f4cb506ad97cdbd0e5aa42f9c58a10573672ee682fe03be70  new
2016-08-18 01:23:30.945645 AddToWallet c8edb1d91ed885e04a1055fde6fb87ecdc6ee7220e0e69954a21a1905bd08192  new
2016-08-18 01:23:30.950825 Received a POST request for / from 127.0.0.1:63113
2016-08-18 01:23:30.950919 ThreadRPCServer method=getbestblockhash
2016-08-18 01:23:30.954369 AddToWallet 73a6b7c722aa598b88d1d1a8904eaf3f660589fbdc3439ee82b5f850fc7b15b1  new
2016-08-18 01:23:30.954500 AddToWallet 8690a40e0c8efb7fdaef84247de5127b82ef95c862e6e6fc81fc8356031b4dc8  new
2016-08-18 01:23:30.954591 AddToWallet f2285cee3ae505239f2c8111a298a8810c8d1b9d171f8ba9660abaeea20976cf  new
2016-08-18 01:23:30.958139 Received a POST request for / from 127.0.0.1:63113
2016-08-18 01:23:30.965591 ThreadRPCServer method=getbalance
2016-08-18 01:23:30.965657 AddToWallet 306903919603fe4f98d7ffa014d412ea049fcd54cab53c1b5975b64c5e4756e2  new
2016-08-18 01:23:30.965890 AddToWallet 271e60900091e68e3ae0cf353df6d6a463b736ec84c24a9d399f807a825bbe3f  new
2016-08-18 01:23:30.965980 AddToWallet be1eb1e8f904f7367a29ca5eff9b5a004c8dd9ba4d293b49fa7b5be2bf1ea64d  new
2016-08-18 01:23:30.968292 Received a POST request for / from 127.0.0.1:63113
2016-08-18 01:23:30.968364 ThreadRPCServer method=stop
2016-08-18 01:23:30.976532 AddToWallet aaa96c08eb8775a51f1e588d83db280c16b47bbcba872d74f32314fce639616f  new
2016-08-18 01:23:30.976642 AddToWallet 53bdc4b09d339c919c53dea611c697c4518e38260ad2190744f057f74bd1a7a7  new
2016-08-18 01:23:30.976712 AddToWallet fbb847867f3135d7febcdbb477afd4309ebb915e359c331332e72efaf4c599b6  new
2016-08-18 01:23:30.976766 AddToWallet 141eb2cef5ccdd8da67f189baba4a4e9f81c4764afc2e57c834021e2dcf8ddb7  new
2016-08-18 01:23:30.976825 AddToWallet 1cf768143a7c688a3bbb3a50d8bc205a3c6986f5d27f0ddd5ae6756374ebba0f  new
2016-08-18 01:23:30.976885 AddToWallet ca27be319fccd3899f823ec1d298fbef32a0c351e44a670ca22d5b32b451dfc4  new
2016-08-18 01:23:30.992053 AddToWallet 6f308d825f343eed97e75f015a75b24d027960c89fd6ab01debf465355210ed0  update
2016-08-18 01:23:30.992243 AddToWallet a52662ed1971e4986832de04673a31d1e78fb3ea756709549ad24ada4424c7e8  new
2016-08-18 01:23:30.993594 AddToWallet c097756702161095fb97018be1c6c5f8105f26a0bd504477d2d8906cd413a1f3  new
2016-08-18 01:23:30.993813 received: headers (82 bytes) peer=2
2016-08-18 01:23:30.993912 SendMessages: sending header 50a069be5d602016fcf691488dfbce82564fa104f19c2adc144125f4fd5c6385 to peer=2
2016-08-18 01:23:30.993929 sending: headers (82 bytes) peer=2
2016-08-18 01:23:30.994025 received: headers (82 bytes) peer=2
2016-08-18 01:23:31.046643 Interrupting HTTP server
2016-08-18 01:23:31.046811 Interrupting HTTP RPC server

Looks like with the reduced delay from fa2d68f, the nodes sync up before the txns all make it into the wallet

laanwj commented at 7:17 AM on August 18, 2016: member

Thanks @theuni, will try reverting that one.

laanwj referenced this in commit 35f64e45c2 on Aug 18, 2016

MarcoFalke commented at 8:43 AM on August 20, 2016: member

Please not that reverting doesn't solve the "bug", it only makes it less likely to appear. (It still does: https://travis-ci.org/bitcoin/bitcoin/jobs/153752648)

laanwj commented at 12:12 PM on August 30, 2016: member

Another one:

segwit.py:
Initializing test directory /tmp/testnbper3lh/31
start_node: bitcoind started, waiting for RPC to come up
start_node: RPC succesfully started
start_node: bitcoind started, waiting for RPC to come up
start_node: RPC succesfully started
start_node: bitcoind started, waiting for RPC to come up
start_node: RPC succesfully started
Verify sigops are counted in GBT with pre-BIP141 rules before the fork
Assertion failed: 899.98200000 != 999.980
Stopping nodes
Not cleaning up dir /tmp/testnbper3lh/31
Failed
stderr:
   File "/home/travis/build/bitcoin/bitcoin/qa/rpc-tests/test_framework/test_framework.py", line 150, in main
    self.run_test()
  File "/home/travis/build/bitcoin/bitcoin/build/../qa/rpc-tests/segwit.py", line 165, in run_test
    assert_equal(self.nodes[1].getbalance(), 20*Decimal("49.999"))
  File "/home/travis/build/bitcoin/bitcoin/qa/rpc-tests/test_framework/util.py", line 504, in assert_equal
    raise AssertionError("%s != %s"%(str(thing1),str(thing2)))

laanwj commented at 12:29 PM on August 30, 2016: member

Random failure in another test (sendheaders.py) after retriggering:

sendheaders.py:
Initializing test directory /tmp/testbc5lzksu/11
start_node: bitcoind started, waiting for RPC to come up
start_node: RPC succesfully started
start_node: bitcoind started, waiting for RPC to come up
start_node: RPC succesfully started
MiniNode: Connecting to Bitcoin Node IP # 127.0.0.1:11088
MiniNode: Connecting to Bitcoin Node IP # 127.0.0.1:11088
Part 1: headers don't start before sendheaders message...
Part 1: success!
Part 2: announce blocks with headers after sendheaders message...
Part 2: success!
Part 3: headers announcements can stop after large reorg, and resume after headers/inv from peer...
Assertion failed: False != True
Stopping nodes
Not cleaning up dir /tmp/testbc5lzksu/11
Failed
stderr:
   File "/home/travis/build/bitcoin/bitcoin/qa/rpc-tests/test_framework/test_framework.py", line 150, in main
    self.run_test()
  File "/home/travis/build/bitcoin/bitcoin/build/../qa/rpc-tests/sendheaders.py", line 416, in run_test
    assert_equal(test_node.check_last_announcement(inv=[tip]), True)
  File "/home/travis/build/bitcoin/bitcoin/qa/rpc-tests/test_framework/util.py", line 504, in assert_equal
    raise AssertionError("%s != %s"%(str(thing1),str(thing2)))
Pass: False, Duration: 19 s

Not sure what is happening here...

MarcoFalke commented at 6:13 PM on September 11, 2016: member

#8680

MarcoFalke closed this on Sep 11, 2016

codablock referenced this in commit f1747c4716 on Sep 19, 2017

codablock referenced this in commit eb50ffb4e7 on Dec 29, 2017

codablock referenced this in commit 7231c66901 on Jan 8, 2018

andvgal referenced this in commit f2099e18f3 on Jan 6, 2019

MarcoFalke locked this on Sep 8, 2021