[WIP] [test] Test abortrescan command.

kallewoof commented at 2:28 am on May 9, 2017: member

Replaces #10225 as it caused intermittent failures for some users.

Difference: gave up on making a “fast running” test and upped the blockchain size and spam count to avoid the scan finishing before the abort call. Moved test down to extended tests.

Test runs in roughly 2 minutes on my local machine. The blockchain generation part takes roughly 1m20s. @jnewbery Does this work on your end?

fanquake added the label Tests on May 9, 2017

jnewbery changes_requested

jnewbery commented at 6:45 pm on May 15, 2017: member

Still flakey for me:

 0→ ./test_runner.py
 1WARNING! The following scripts are not being run: ['p2p-fullblocktest.py', 'mempool_spendcoinbase.py', 'fundrawtransaction.py', 'mempool_resurrect_test.py', 'net.py', 'import-rescan.py', 'disconnect_ban.py', 'zapwallettxes.py', 'mempool_limit.py', 'multi_rpc.py', 'preciousblock.py', 'rawtransactions.py', 'importmulti.py', 'blockchain.py', 'bip68-112-113-p2p.py', 'httpbasics.py', 'listsinceblock.py', 'disablewallet.py', 'prioritise_transaction.py', 'invalidtxrequest.py', 'receivedby.py', 'importprunedfunds.py', 'listtransactions.py', 'wallet.py', 'p2p-compactblocks.py', 'wallet-accounts.py', 'signrawtransactions.py', 'nodehandling.py', 'p2p-segwit.py', 'nulldummy.py', 'keypool.py', 'signmessages.py', 'p2p-leaktests.py', 'wallet-hd.py', 'segwit.py', 'merkle_blocks.py', 'reindex.py', 'bumpfee.py', 'mempool_persist.py', 'wallet-dump.py', 'rest.py', 'invalidblockrequest.py', 'getchaintips.py', 'sendheaders.py', 'rpcnamedargs.py', 'proxy_test.py', 'decodescript.py', 'p2p-mempool.py', 'zmq_test.py', 'mempool_reorg.py', 'walletbackup.py', 'maxblocksinflight.py', 'p2p-versionbits-warning.py', 'abandonconflict.py']. Check the test lists in test_runner.py.
 2...........................................................
 3import-abort-rescan.py --portseed=3 passed, Duration: 30 s
 4......
 5import-abort-rescan.py --portseed=2 failed, Duration: 33 s
 6
 7stdout:
 82017-05-15 18:41:26.479000 TestFramework (INFO): Initializing test directory /tmp/user/1000/test3cj9jwid/166
 92017-05-15 18:41:31.202000 TestFramework (INFO): Creating blocks with transactions ...
102017-05-15 18:41:50.352000 TestFramework (INFO): Sending to shared address ...
112017-05-15 18:41:50.422000 TestFramework (INFO): Importing address in background thread ...
122017-05-15 18:41:50.423000 TestFramework (INFO): Attempting to abort scan ...
132017-05-15 18:41:50.437000 TestFramework (INFO): Waiting for import thread to die ...
142017-05-15 18:41:50.538000 TestFramework (ERROR): Assertion failed
15Traceback (most recent call last):
16  File "/home/ubuntu/bitcoin/test/functional/test_framework/test_framework.py", line 148, in main
17    self.run_test()
18  File "/home/ubuntu/bitcoin/test/functional/import-abort-rescan.py", line 62, in run_test
19    assert_equal(self.nodes[1].getbalance(), balances[1])
20  File "/home/ubuntu/bitcoin/test/functional/test_framework/util.py", line 408, in assert_equal
21    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
22AssertionError: not(2475.12300000 == 2475.00000000)
232017-05-15 18:41:50.539000 TestFramework (INFO): Stopping nodes
242017-05-15 18:41:59.604000 TestFramework (WARNING): Not cleaning up dir /tmp/user/1000/test3cj9jwid/166
252017-05-15 18:41:59.604000 TestFramework (ERROR): Test failed. Test logging available at /tmp/user/1000/test3cj9jwid/166/test_framework.log
26
27
28stderr:
29
30
31..........
32import-abort-rescan.py --portseed=1 failed, Duration: 39 s
33
34stdout:
352017-05-15 18:41:26.476000 TestFramework (INFO): Initializing test directory /tmp/user/1000/test89_pqhmk/167
362017-05-15 18:41:31.503000 TestFramework (INFO): Creating blocks with transactions ...
372017-05-15 18:41:50.205000 TestFramework (INFO): Sending to shared address ...
382017-05-15 18:41:50.333000 TestFramework (INFO): Importing address in background thread ...
392017-05-15 18:41:50.334000 TestFramework (INFO): Attempting to abort scan ...
402017-05-15 18:41:54.919000 TestFramework (ERROR): Assertion failed
41Traceback (most recent call last):
42  File "/home/ubuntu/bitcoin/test/functional/test_framework/test_framework.py", line 148, in main
43    self.run_test()
44  File "/home/ubuntu/bitcoin/test/functional/import-abort-rescan.py", line 52, in run_test
45    assert abortres # if false, we failed to abort
46AssertionError
472017-05-15 18:41:54.919000 TestFramework (INFO): Stopping nodes
482017-05-15 18:42:05.038000 TestFramework (WARNING): Not cleaning up dir /tmp/user/1000/test89_pqhmk/167
492017-05-15 18:42:05.038000 TestFramework (ERROR): Test failed. Test logging available at /tmp/user/1000/test89_pqhmk/167/test_framework.log
50
51
52stderr:

Try running in parallel with pruning.py to reproduce this.

kallewoof renamed this:
~~[test] Test abortrescan command.~~
[WIP] [test] Test abortrescan command.
on May 16, 2017

kallewoof force-pushed on Aug 10, 2017

kallewoof commented at 9:27 am on August 10, 2017: member

@jnewbery Sorry for taking so long. Assuming there is a race condition where your side ends up scanning the chain before the abort makes it through, this should definitely fix it, I think. The tests take ~4 mins on my machine, but they’re already in extended tests. If this still shows intermittent failures on your end, I will need to go back to the drawing board, as it has to be something other than the above.

jnewbery commented at 1:55 pm on August 14, 2017: member

This may be specific to my local environment, but if I try to run this test multiple times in parallel, I get failures:

 0→ ./test_runner.py $(for i in {1..40}; do echo -n 'import-abort-rescan '; done)
 1Temporary test directory at /tmp/user/1000/bitcoin_test_runner_20170814_134812
 2WARNING! The following scripts are not being run: ['test_bitcoincli.py', 'bip65-cltv.py', 'wallet-labels.py', 'p2p-fullblocktest2.py', 'bitcoin_cli.py', 'keypool-topup.py', 'wallet-hd-restore.py', 'disablehot.py', 'blocknotify.py', 'getblocktemplate_proposals.py', 'resendwallettransactions.py', 'minchainwork.py', 'walletnotify.py', 'bipdersig.py', 'datalogging.py']. Check the test lists in test_runner.py.
 3.......................................................................................................................................................................................
 4import-abort-rescan.py failed, Duration: 97 s
 5
 6stdout:
 72017-08-14 13:48:33.367000 TestFramework (INFO): Initializing test directory /tmp/user/1000/bitcoin_test_runner_20170814_134812/import-abort-rescan_118
 82017-08-14 13:48:38.719000 TestFramework (INFO): Creating blocks with transactions ...
 92017-08-14 13:48:38.720000 TestFramework (INFO): ...  0%
102017-08-14 13:49:10.376000 TestFramework (ERROR): JSONRPC error
11Traceback (most recent call last):
12  File "/home/ubuntu/bitcoin/test/functional/test_framework/authproxy.py", line 169, in _get_response
13    http_response = self.__conn.getresponse()
14  File "/usr/lib/python3.5/http/client.py", line 1197, in getresponse
15    response.begin()
16  File "/usr/lib/python3.5/http/client.py", line 297, in begin
17    version, status, reason = self._read_status()
18  File "/usr/lib/python3.5/http/client.py", line 258, in _read_status
19    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
20  File "/usr/lib/python3.5/socket.py", line 575, in readinto
21    return self._sock.recv_into(b)
22socket.timeout: timed out
23
24During handling of the above exception, another exception occurred:
25
26Traceback (most recent call last):
27  File "/home/ubuntu/bitcoin/test/functional/test_framework/test_framework.py", line 149, in main
28    self.run_test()
29  File "/home/ubuntu/bitcoin/test/functional/import-abort-rescan.py", line 32, in run_test
30    self.nodes[0].sendtoaddress(addr, 0.1)
31  File "/home/ubuntu/bitcoin/test/functional/test_framework/coverage.py", line 46, in __call__
32    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
33  File "/home/ubuntu/bitcoin/test/functional/test_framework/authproxy.py", line 152, in __call__
34    response = self._request('POST', self.__url.path, postdata.encode('utf-8'))
35  File "/home/ubuntu/bitcoin/test/functional/test_framework/authproxy.py", line 126, in _request
36    return self._get_response()
37  File "/home/ubuntu/bitcoin/test/functional/test_framework/authproxy.py", line 176, in _get_response
38    self.__conn.timeout)})
39test_framework.authproxy.JSONRPCException: 'sendtoaddress' RPC took longer than 30.000000 seconds. Consider using larger timeout for calls that take longer to return. (-344)
402017-08-14 13:49:10.377000 TestFramework (INFO): Stopping nodes
412017-08-14 13:49:10.377000 TestFramework (ERROR): Unable to stop node
42Traceback (most recent call last):
43  File "/home/ubuntu/bitcoin/test/functional/test_framework/test_framework.py", line 254, in stop_node
44    self.nodes[i].stop()
45  File "/home/ubuntu/bitcoin/test/functional/test_framework/coverage.py", line 46, in __call__
46    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
47  File "/home/ubuntu/bitcoin/test/functional/test_framework/authproxy.py", line 152, in __call__
48    response = self._request('POST', self.__url.path, postdata.encode('utf-8'))
49  File "/home/ubuntu/bitcoin/test/functional/test_framework/authproxy.py", line 125, in _request
50    self.__conn.request(method, path, postdata, headers)
51  File "/usr/lib/python3.5/http/client.py", line 1106, in request
52    self._send_request(method, url, body, headers)
53  File "/usr/lib/python3.5/http/client.py", line 1141, in _send_request
54    self.putrequest(method, url, **skips)
55  File "/usr/lib/python3.5/http/client.py", line 974, in putrequest
56    raise CannotSendRequest(self.__state)
57http.client.CannotSendRequest: Request-sent

I’m running this in an ubuntu VM with quite slow spinning disk i/o. @kallewoof - if you run ./test_runner.py $(for i in {1..40}; do echo -n 'import-abort-rescan '; done) do you get all success?

MarcoFalke commented at 2:14 pm on August 14, 2017: member

Just fyi

0./test_runner.py $(for i in {1..40}; do echo -n 'import-abort-rescan '; done)

is passing for me on an ssd.

jnewbery commented at 3:01 pm on August 14, 2017: member

Thanks @MarcoFalke - probably caused by my slow disk in that case.

MarcoFalke commented at 3:06 pm on August 14, 2017: member

Yeah. Though, I think tests should run and pass on all platforms that are capable of running Bitcoin Core.

in test/functional/import-abort-rescan.py:12 in 4eb87c27ee outdated

 9+2. Subsequent rescan catches the aborted address UTXO
10+"""
11+
12+from test_framework.test_framework import BitcoinTestFramework
13+from test_framework.util import (assert_equal, get_rpc_proxy)
14+from decimal import Decimal

jnewbery commented at 5:14 pm on August 14, 2017:

nit: prefer imports to be in PEP-8 ordering (standard libraries first)

kallewoof commented at 2:33 am on August 15, 2017:

I put decimal, threading, and time imports at top.

in test/functional/import-abort-rescan.py:19 in 4eb87c27ee outdated

14+from decimal import Decimal
15+import threading # for bg importprivkey
16+import time      # for sleep
17+
18+class ImportAbortRescanTest(BitcoinTestFramework):
19+    def __init__(self):

jnewbery commented at 5:14 pm on August 14, 2017:

No need to override method if you’re just calling into super()

in test/functional/import-abort-rescan.py:29 in 4eb87c27ee outdated

24+        # Generate for BTC
25+        self.nodes[0].generate(300)
26+        self.log.info("Creating blocks with transactions ...")
27+        # Make blocks with spam to cause rescan delay
28+        for i in range(200):
29+            if i % 50 == 0: self.log.info("... %2.f%%", 100.0 / 200.0 * i)

jnewbery commented at 5:16 pm on August 14, 2017:

nit: if block should appear on the next line. Same for the if xxxxx: break lines below

in test/functional/import-abort-rescan.py:62 in 4eb87c27ee outdated

57+        for i in range(10):
58+            time.sleep(0.1)
59+            deadres = not importthread.isAlive()
60+            if deadres: break
61+
62+        assert deadres # if false, importthread did not die soon enough

jnewbery commented at 5:18 pm on August 14, 2017:

nit: prefer assert deadres, "importthread did not die soon enough" (so the error message is delivered to the user)

kallewoof commented at 2:34 am on August 15, 2017:

Nice.. I didn’t know you could do that.

jnewbery commented at 5:20 pm on August 14, 2017: member

A few nits.

This still seems flakey for me, so should get some wider testing before being merged.

kallewoof commented at 2:57 am on August 15, 2017: member

@jnewbery your bash line runs fine on my end.

socket.timeout: timed out? Hum.. any ideas on how to fix that one?

in test/functional/import-abort-rescan.py:18 in 7da6e01bdf outdated

13+import threading # for bg importprivkey
14+import time      # for sleep
15+from test_framework.test_framework import BitcoinTestFramework
16+from test_framework.util import (assert_equal, get_rpc_proxy)
17+
18+class ImportAbortRescanTest(BitcoinTestFramework):

MarcoFalke commented at 7:58 am on August 15, 2017:

It seems you are not specifying the constructor (__init__). Thus 2 additional nodes are spun up and remain unused.

kallewoof commented at 8:21 am on August 15, 2017:

Good point. Fixed.

jnewbery commented at 1:18 pm on August 15, 2017: member

socket.timeout: timed out probably means that running this test 4 times in parallel is too much for my VM, and one of the rpc calls timed out.

in test/functional/import-abort-rescan.py:56 in e90d996420 outdated

51+        for i in range(2000):
52+            time.sleep(0.001)
53+            abortres = self.nodes[1].abortrescan()
54+            if abortres:
55+                break
56+        assert abortres # if false, we failed to abort

jnewbery commented at 1:21 pm on August 15, 2017:

nit: could change this to:

0assert abortres, "abortrescan call failed"

kallewoof commented at 5:17 am on August 16, 2017:

Fixed, thanks!

jnewbery commented at 2:05 pm on August 15, 2017: member

One small nit, but otherwise looks good.

MarcoFalke commented at 3:05 pm on August 15, 2017: member

Please squash your commits if this is no longer WIP

kallewoof force-pushed on Aug 16, 2017

kallewoof renamed this:
~~[WIP] [test] Test abortrescan command.~~
[test] Test abortrescan command.
on Aug 16, 2017

kallewoof commented at 5:17 am on August 16, 2017: member

@MarcoFalke Squashed & removed ‘[WIP]’ from title.

in test/functional/import-abort-rescan.py:19 in fef5ec5f84 outdated

14+import time      # for sleep
15+from test_framework.test_framework import BitcoinTestFramework
16+from test_framework.util import (assert_equal, get_rpc_proxy)
17+
18+class ImportAbortRescanTest(BitcoinTestFramework):
19+    def __init__(self):

promag commented at 1:52 pm on September 13, 2017:

Replace with

0    def set_test_params(self):
1        self.num_nodes = 2

in test/functional/import-abort-rescan.py:14 in fef5ec5f84 outdated

 9+2. Subsequent rescan catches the aborted address UTXO
10+"""
11+
12+from decimal import Decimal
13+import threading # for bg importprivkey
14+import time      # for sleep

promag commented at 1:53 pm on September 13, 2017:

Change and remove comment:

0from time import sleep

The same above.

in test/functional/import-abort-rescan.py:9 in fef5ec5f84 outdated

0@@ -0,0 +1,75 @@
1+#!/usr/bin/env python3
2+# Copyright (c) 2017 The Bitcoin Core developers
3+# Distributed under the MIT software license, see the accompanying
4+# file COPYING or http://www.opensource.org/licenses/mit-license.php.
5+"""Test wallet import RPCs.
6+
7+Test rescan behavior of importprivkey when aborted. The test ensures that:
8+1. The abortrescan command indeed stops the rescan process.
9+2. Subsequent rescan catches the aborted address UTXO

promag commented at 1:53 pm on September 13, 2017:

Nit, missing period.

in test/functional/import-abort-rescan.py:8 in fef5ec5f84 outdated

0@@ -0,0 +1,75 @@
1+#!/usr/bin/env python3
2+# Copyright (c) 2017 The Bitcoin Core developers
3+# Distributed under the MIT software license, see the accompanying
4+# file COPYING or http://www.opensource.org/licenses/mit-license.php.
5+"""Test wallet import RPCs.
6+
7+Test rescan behavior of importprivkey when aborted. The test ensures that:
8+1. The abortrescan command indeed stops the rescan process.

promag commented at 1:54 pm on September 13, 2017:

Nit, use unordered, ie, - The abortrescan ... .

kallewoof commented at 2:51 am on September 19, 2017:

I’m not sure what the reason for this is. It is easier to refer to a point by number, e.g. “this test is no longer checking the 3rd point mentioned in the comment”.

in test/functional/import-abort-rescan.py:25 in fef5ec5f84 outdated

21+        self.num_nodes = 2
22+
23+    def run_test(self):
24+        # Generate for BTC
25+        self.nodes[0].generate(300)
26+        self.log.info("Creating blocks with transactions ...")

promag commented at 2:11 pm on September 13, 2017:

@jnewbery wdyt about moving this to util.py, like def generate_load(node, blocks, transactions): or whatever?

jnewbery commented at 6:18 pm on September 19, 2017:

I don’t think it makes sense to move code up into the test_framework directory unless it’s being used by more than one test script. I don’t see the need here (unless you think you can refactor other test scripts to use this and reduce LOC)

maxgiraldo commented at 4:44 pm on December 12, 2017:

Would it make sense to take advantage of mine_large_block or is that overkill in this context? Might make this test more concise.

promag commented at 2:13 pm on September 13, 2017: member

Missing test for when abortrescan returns false.

kallewoof force-pushed on Sep 19, 2017

in test/functional/import-abort-rescan.py:14 in adc27e086d outdated

 9+2. Subsequent rescan catches the aborted address UTXO.
10+"""
11+
12+from decimal import Decimal
13+import threading # for bg importprivkey
14+import sleep from time

jnewbery commented at 6:36 pm on September 19, 2017:

invalid syntax. Should be from time import sleep

kallewoof force-pushed on Sep 20, 2017

maxgiraldo commented at 0:14 am on December 10, 2017: none

I was able to get most of the tests to pass running in parallel on the following:

Ubuntu 16.04.2 LTS x86_64 1 Core 2.50GHz CPU 1GB RAM HDD
Debian GNU/Linux 8.9 x86_64 1 Core 2.80 GHz CPU 2GB RAM HDD
MacOS High Sierra x86_64 2 Cores 3.3 GHz CPU 16GB RAM SSD 39/40 tests passed successfully

Error:

 0stdout:
 12017-12-09 22:59:54.102000 TestFramework (INFO): Initializing test directory /var/folders/db/5xcqh4b57l7380mcv8c0kj8r0000gn/T/bitcoin_test_runner_20171209_170923/import-abort-rescan_85
 22017-12-09 23:00:20.768000 TestFramework (INFO): Creating blocks with transactions ...
 32017-12-09 23:00:20.782000 TestFramework (INFO): ...  0%
 42017-12-09 23:02:37.124000 TestFramework (INFO): ... 25%
 52017-12-09 23:04:59.728000 TestFramework (INFO): ... 50%
 62017-12-09 23:07:31.909000 TestFramework (INFO): ... 75%
 72017-12-09 23:10:03.214000 TestFramework (INFO): Sending to shared address ...
 82017-12-09 23:10:04.581000 TestFramework (ERROR): Unexpected exception caught during testing
 9Traceback (most recent call last):
10  File "/bitcoin/test/functional/test_framework/test_framework.py", line 120, in main
11    self.run_test()
12  File "/bitcoin/test/functional/import-abort-rescan.py", line 40, in run_test
13    self.sync_all()
14  File "/bitcoin/test/functional/test_framework/test_framework.py", line 328, in sync_all
15    sync_blocks(group)
16  File "/bitcoin/test/functional/test_framework/util.py", line 368, in sync_blocks
17    maxheight = max(x.getblockcount() for x in rpc_connections)
18  File "/bitcoin/test/functional/test_framework/util.py", line 368, in <genexpr>
19    maxheight = max(x.getblockcount() for x in rpc_connections)
20  File "/bitcoin/test/functional/test_framework/coverage.py", line 47, in __call__
21    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
22  File "/bitcoin/test/functional/test_framework/authproxy.py", line 136, in __call__
23    response = self._request('POST', self.__url.path, postdata.encode('utf-8'))
24  File "/bitcoin/test/functional/test_framework/authproxy.py", line 106, in _request
25    self.__conn.request(method, path, postdata, headers)
26  File "/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 1239, in request
27    self._send_request(method, url, body, headers, encode_chunked)
28  File "/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 1285, in _send_request
29    self.endheaders(body, encode_chunked=encode_chunked)
30  File "/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 1234, in endheaders
31    self._send_output(message_body, encode_chunked=encode_chunked)
32  File "/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 1065, in _send_output
33    self.send(chunk)
34  File "/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 986, in send
35    self.sock.sendall(data)
36OSError: [Errno 41] Protocol wrong type for socket
372017-12-09 23:10:04.605000 TestFramework (INFO): Stopping nodes
382017-12-09 23:10:04.623000 TestFramework.node1 (ERROR): Unable to stop node.
39Traceback (most recent call last):
40  File "/bitcoin/test/functional/test_framework/test_node.py", line 125, in stop_node
41    self.stop()
42  File "/bitcoin/test/functional/test_framework/coverage.py", line 47, in __call__
43    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
44  File "/bitcoin/test/functional/test_framework/authproxy.py", line 136, in __call__
45    response = self._request('POST', self.__url.path, postdata.encode('utf-8'))
46  File "/bitcoin/test/functional/test_framework/authproxy.py", line 106, in _request
47    self.__conn.request(method, path, postdata, headers)
48  File "/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 1239, in request
49    self._send_request(method, url, body, headers, encode_chunked)
50  File "/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 1250, in _send_request
51    self.putrequest(method, url, **skips)
52  File "/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 1108, in putrequest
53    raise CannotSendRequest(self.__state)
54http.client.CannotSendRequest: Request-sent
55
56stderr:
57Traceback (most recent call last):
58  File "/bitcoin/test/functional/import-abort-rescan.py", line 77, in <module>
59    ImportAbortRescanTest().main()
60  File "/bitcoin/test/functional/test_framework/test_framework.py", line 143, in main
61    self.stop_nodes()
62  File "/bitcoin/test/functional/test_framework/test_framework.py", line 277, in stop_nodes
63    node.wait_until_stopped()
64  File "/bitcoin/test/functional/test_framework/test_node.py", line 151, in wait_until_stopped
65    wait_until(self.is_node_stopped, timeout=timeout)
66  File "/bitcoin/test/functional/test_framework/util.py", line 222, in wait_until
67    assert_greater_than(timeout, time.time())
68  File "/bitcoin/test/functional/test_framework/util.py", line 42, in assert_greater_than
69    raise AssertionError("%s <= %s" % (str(thing1), str(thing2)))
70AssertionError: 1512861065.40589 <= 1512861065.4063418

kallewoof commented at 3:38 am on December 11, 2017: member

@maxgiraldo Thanks for testing! I tried on same mac set up (except more cores) doing

0./test_runner.py $(for i in {1..40}; do echo -n 'import-abort-rescan '; done)

and it is working on my end. What command are you using to run the tests?

maxgiraldo commented at 3:21 pm on December 11, 2017: none

@kallewoof No problem! I’m using ./test_runner.py $(for i in {1..40}; do echo -n 'import-abort-rescan '; done) as well. I ran the tests again on Mac about three more times and got the same error, but only on the last run.

kallewoof commented at 4:09 am on December 12, 2017: member

@maxgiraldo After running it for a long time I managed to reproduce. Looking into it now.

kallewoof commented at 3:44 am on December 13, 2017: member

Hum. I can’t reproduce this without running for hours. It feels like something is being exhausted, triggering the issue, but even after running for several hours I don’t see any spikes in resource usage and drive has 100 GB free. @jnewbery any thoughts on why “OSError: [Errno 41] Protocol wrong type for socket” would happen occasionally for

0    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)

(test_framework/coverage.py#46)?

maxgiraldo commented at 3:06 pm on December 13, 2017: none

@kallewoof Seems to be a MacOS/OS X-specific kernel issue, which throws the error code EPROTOTYPE when you attempt to do a TCP send syscall while a socket is not yet connected or is in the process of being torn down.*

Source Code *Source

jnewbery commented at 9:35 pm on December 13, 2017: member

Hmmm, I’ve definitely read that blog post before, but I can’t remember what exactly the context was! @maxgiraldo - perhaps you could add additional exception handling here: https://github.com/bitcoin/bitcoin/blob/d4991c0cbb8a5464add1b64268eccdbfd3026d6e/test/functional/test_framework/authproxy.py#L108

Something like:

0        except OSError as e:
1            if e.errno == 42:
2                # EPROTOTYPE - OS X issue: a TCP send syscall while a socket is
3                # not yet connected or is in the process of being torn down.
4                self.__conn.close()
5                self.__conn.request(method, path, postdata, headers)
6                return self._get_response()
7            else:
8                raise

You could add a print statement or pdb breakpoint in there to confirm that you can reproduce and that this fixes this:

0        except OSError as e:
1            if e.errno == 42:
2                # EPROTOTYPE - OS X issue: a TCP send syscall while a socket is
3                import pdb; pbd.set_trace()

Do you think this error is specific to this new test, or are you able to reproduce it on other tests? If it’s not specific to this test, perhaps you can open a new issue or PR to track it.

kallewoof commented at 0:40 am on December 14, 2017: member

I can reproduce as well, but it sometimes takes hours. Will try your patch in a couple hours on my end. I’ll push a commit so @maxgiraldo can test it too if he hasn’t tried it manually already.

kallewoof commented at 5:22 am on December 18, 2017: member

Different error now. Something very weird is going on with networking here.

 02017-12-18 03:53:15.458000 TestFramework (INFO): Initializing test directory /var/folders/b8/znqr8hj918772gfmd875gzgdd3ypz1/T/bitcoin_test_runner_20171218_125257/import-abort-rescan_635
 12017-12-18 03:53:21.588000 TestFramework (INFO): Creating blocks with transactions ...
 22017-12-18 03:53:21.592000 TestFramework (INFO): ...  0%
 32017-12-18 03:54:49.215000 TestFramework (INFO): ... 25%
 42017-12-18 03:56:23.323000 TestFramework (INFO): ... 50%
 52017-12-18 03:57:56.488000 TestFramework (INFO): ... 75%
 62017-12-18 03:59:29.920000 TestFramework (INFO): Sending to shared address ...
 72017-12-18 03:59:30.218000 TestFramework (ERROR): Unexpected exception caught during testing
 8Traceback (most recent call last):
 9  File "<dir>/bitcoin/test/functional/test_framework/test_framework.py", line 117, in main
10    self.run_test()
11  File "<dir>/bitcoin/test/functional/import-abort-rescan.py", line 39, in run_test
12    self.sync_all()
13  File "<dir>/bitcoin/test/functional/test_framework/test_framework.py", line 320, in sync_all
14    sync_blocks(group)
15  File "<dir>/bitcoin/test/functional/test_framework/util.py", line 350, in sync_blocks
16    maxheight = max(x.getblockcount() for x in rpc_connections)
17  File "<dir>/bitcoin/test/functional/test_framework/util.py", line 350, in <genexpr>
18    maxheight = max(x.getblockcount() for x in rpc_connections)
19  File "<dir>/bitcoin/test/functional/test_framework/coverage.py", line 46, in __call__
20    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
21  File "<dir>/bitcoin/test/functional/test_framework/authproxy.py", line 162, in __call__
22    response = self._request('POST', self.__url.path, postdata.encode('utf-8'))
23  File "<dir>/bitcoin/test/functional/test_framework/authproxy.py", line 126, in _request
24    return self._get_response()
25  File "<dir>/bitcoin/test/functional/test_framework/authproxy.py", line 179, in _get_response
26    http_response = self.__conn.getresponse()
27  File "/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 1331, in getresponse
28    response.begin()
29  File "/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 297, in begin
30    version, status, reason = self._read_status()
31  File "/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 258, in _read_status
32    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
33  File "/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/socket.py", line 586, in readinto
34    return self._sock.recv_into(b)
35ConnectionResetError: [Errno 54] Connection reset by peer
362017-12-18 03:59:30.332000 TestFramework (INFO): Stopping nodes
372017-12-18 03:59:32.775000 TestFramework (WARNING): Not cleaning up dir /var/folders/b8/znqr8hj918772gfmd875gzgdd3ypz1/T/bitcoin_test_runner_20171218_125257/import-abort-rescan_635
382017-12-18 03:59:32.775000 TestFramework (ERROR): Test failed. Test logging available at /var/folders/b8/znqr8hj918772gfmd875gzgdd3ypz1/T/bitcoin_test_runner_20171218_125257/import-abort-rescan_635/test_framework.log

kallewoof commented at 5:25 am on December 18, 2017: member

Pushed commit with fix in it. This still breaks on my end after running for awhile.

kallewoof force-pushed on Dec 18, 2017

[test] Test abortrescan command. 53c7c1a843

f'authproxy.py patch by jnewbery da91c46f62

kallewoof force-pushed on Dec 18, 2017

in test/functional/test_framework/authproxy.py:116 in da91c46f62 outdated

111@@ -112,6 +112,16 @@ def _request(self, method, path, postdata):
112                 return self._get_response()
113             else:
114                 raise
115+        except OSError as e:
116+            if e.errno == 42:

maxgiraldo commented at 3:21 pm on December 18, 2017:

The errno is actually 41; to avoid hardcoding the value, I would use from errno import EPROTOTYPE and then:

0if e.errno == EPROTOTYPE:
1   ...

kallewoof commented at 2:33 am on December 20, 2017:

Oops, good catch.

kallewoof commented at 1:20 am on December 21, 2017: member

Connection reset by peer after a shortish while. Very curious.

 02017-12-21 01:10:24.464000 TestFramework (INFO): Initializing test directory /var/folders/b8/znqr8hj918772gfmd875gzgdd3ypz1/T/bitcoin_test_runner_20171221_100356/import-abort-rescan_961
 12017-12-21 01:10:40.349000 TestFramework (INFO): Creating blocks with transactions ...
 22017-12-21 01:10:40.352000 TestFramework (INFO): ...  0%
 32017-12-21 01:11:50.257000 TestFramework (INFO): ... 25%
 42017-12-21 01:13:02.097000 TestFramework (INFO): ... 50%
 52017-12-21 01:14:12.874000 TestFramework (INFO): ... 75%
 62017-12-21 01:15:22.978000 TestFramework (INFO): Sending to shared address ...
 72017-12-21 01:15:23.566000 TestFramework (ERROR): Unexpected exception caught during testing
 8Traceback (most recent call last):
 9  File "/Users/karljohan-alm/workspace/bitcoin-kw/test/functional/test_framework/test_framework.py", line 118, in main
10    self.run_test()
11  File "/Users/karljohan-alm/workspace/bitcoin-kw/test/functional/import-abort-rescan.py", line 39, in run_test
12    self.sync_all()
13  File "/Users/karljohan-alm/workspace/bitcoin-kw/test/functional/test_framework/test_framework.py", line 313, in sync_all
14    sync_blocks(group)
15  File "/Users/karljohan-alm/workspace/bitcoin-kw/test/functional/test_framework/util.py", line 368, in sync_blocks
16    maxheight = max(x.getblockcount() for x in rpc_connections)
17  File "/Users/karljohan-alm/workspace/bitcoin-kw/test/functional/test_framework/util.py", line 368, in <genexpr>
18    maxheight = max(x.getblockcount() for x in rpc_connections)
19  File "/Users/karljohan-alm/workspace/bitcoin-kw/test/functional/test_framework/coverage.py", line 47, in __call__
20    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
21  File "/Users/karljohan-alm/workspace/bitcoin-kw/test/functional/test_framework/authproxy.py", line 147, in __call__
22    response = self._request('POST', self.__url.path, postdata.encode('utf-8'))
23  File "/Users/karljohan-alm/workspace/bitcoin-kw/test/functional/test_framework/authproxy.py", line 108, in _request
24    return self._get_response()
25  File "/Users/karljohan-alm/workspace/bitcoin-kw/test/functional/test_framework/authproxy.py", line 164, in _get_response
26    http_response = self.__conn.getresponse()
27  File "/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 1331, in getresponse
28    response.begin()
29  File "/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 297, in begin
30    version, status, reason = self._read_status()
31  File "/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 258, in _read_status
32    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
33  File "/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/socket.py", line 586, in readinto
34    return self._sock.recv_into(b)
35ConnectionResetError: [Errno 54] Connection reset by peer
362017-12-21 01:15:23.570000 TestFramework (INFO): Stopping nodes
372017-12-21 01:15:24.265000 TestFramework (WARNING): Not cleaning up dir /var/folders/b8/znqr8hj918772gfmd875gzgdd3ypz1/T/bitcoin_test_runner_20171221_100356/import-abort-rescan_961
382017-12-21 01:15:24.269000 TestFramework (ERROR): Test failed. Test logging available at /var/folders/b8/znqr8hj918772gfmd875gzgdd3ypz1/T/bitcoin_test_runner_20171221_100356/import-abort-rescan_961/test_framework.log
392017-12-21 01:15:24.270000 TestFramework (ERROR): Hint: Call /Users/karljohan-alm/workspace/bitcoin-kw/test/functional/combine_logs.py '/var/folders/b8/znqr8hj918772gfmd875gzgdd3ypz1/T/bitcoin_test_runner_20171221_100356/import-abort-rescan_961' to consolidate all logs

f'use EPROTOTYPE 3ed3dd5844

kallewoof renamed this:
~~[test] Test abortrescan command.~~
[WIP] [test] Test abortrescan command.
on Feb 5, 2018

laanwj commented at 6:59 pm on March 7, 2018: member

Closing for now, as this PR seems to be dormant, let me know when you want to pick it up again and I’ll reopen.

laanwj closed this on Mar 7, 2018

kallewoof deleted the branch on Oct 17, 2019

DrahtBot locked this on Dec 16, 2021

[WIP] [test] Test abortrescan command. #10367