test: fix test abort for high timeout values (and `--timeout-factor 0`) #25950

theStack commented at 1:38 AM on August 29, 2022: contributor

On master, the functional tests's option --timeout-factor 0 (which according to the test docs and parameter description should disable the RPC timeouts) currently fails, same as high values like --timeout-factor 999999:

$ ./test/functional/wallet_basic.py --timeout-factor 0
2022-08-29T01:26:39.561000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test_f24yxzp5
2022-08-29T01:26:40.262000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/home/honey/bitcoin/test/functional/test_framework/test_framework.py", line 549, in start_nodes
    node.wait_for_rpc_connection()
  File "/home/honey/bitcoin/test/functional/test_framework/test_node.py", line 234, in wait_for_rpc_connection
    rpc.getblockcount()
  File "/home/honey/bitcoin/test/functional/test_framework/coverage.py", line 49, in __call__
    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
  File "/home/honey/bitcoin/test/functional/test_framework/authproxy.py", line 142, in __call__
    response, status = self._request('POST', self.__url.path, postdata.encode('utf-8'))
  File "/home/honey/bitcoin/test/functional/test_framework/authproxy.py", line 107, in _request
    self.__conn.request(method, path, postdata, headers)
  File "/usr/local/lib/python3.9/http/client.py", line 1285, in request
    self._send_request(method, url, body, headers, encode_chunked)
  File "/usr/local/lib/python3.9/http/client.py", line 1331, in _send_request
    self.endheaders(body, encode_chunked=encode_chunked)
  File "/usr/local/lib/python3.9/http/client.py", line 1280, in endheaders
    self._send_output(message_body, encode_chunked=encode_chunked)
  File "/usr/local/lib/python3.9/http/client.py", line 1040, in _send_output
    self.send(msg)
  File "/usr/local/lib/python3.9/http/client.py", line 980, in send
    self.connect()
  File "/usr/local/lib/python3.9/http/client.py", line 946, in connect
    self.sock = self._create_connection(
  File "/usr/local/lib/python3.9/socket.py", line 844, in create_connection
    raise err
  File "/usr/local/lib/python3.9/socket.py", line 832, in create_connection
    sock.connect(sa)
OSError: [Errno 22] Invalid argument

This is caused by a high timeout value that Python's HTTP(S) client library can't cope with. Fix this by clamping down the connection's set timeout value in AuthProxy. The change can easily be tested by running an arbitrary test with --timeout-factor 0 on master (should fail), on this PR (should pass) and on this PR with the clamping value increased by 1 (should fail).

// EDIT: The behaviour was observed on OpenBSD 7.1 and Python 3.9.12.

DrahtBot added the label Tests on Aug 29, 2022

in test/functional/test_framework/authproxy.py:81 in 649d3db13c outdated

  77 | @@ -78,7 +78,9 @@ def __init__(self, service_url, service_name=None, timeout=HTTP_TIMEOUT, connect
  78 |          passwd = None if self.__url.password is None else self.__url.password.encode('utf8')
  79 |          authpair = user + b':' + passwd
  80 |          self.__auth_header = b'Basic ' + base64.b64encode(authpair)
  81 | -        self.timeout = timeout
  82 | +        # larger values of the timeout cause a "Invalid argument"

yancyribbens commented at 8:33 AM on August 29, 2022:

I think this should be an "Invalid argument" not a.

theStack commented at 9:20 AM on August 29, 2022:

Thanks, done.

theStack force-pushed on Aug 29, 2022

jonatack commented at 1:27 PM on August 31, 2022: contributor

Interesting. I use --timeout-factor locally to avoid the functional tests timing out on my slow Debian 5.18.16-1 (2022-08-10) x86_64 toaster with Python 3.10.6 anid haven't been seeing any issue. It may possibly be platform (or python version?) specific.

furszy commented at 1:48 PM on August 31, 2022: member

Tested it on OSX, python 2.7.18 and 3.9.13 and it works fine. Then tested it on Ubuntu 20.04.1 LTS, python 3.8.10 and it didn't.

yancyribbens commented at 11:29 AM on September 3, 2022: contributor

I confirmed that --timeout-factor 0 blows up with a stack trace (running FreeBSD). It looks like the problems stems from here. timeout-factor is a multiplying factor, so if it's 0 the multiple becomes 60 * 99999 = 5999940 minutes. I feel like this is a mistake introduced by this PR. If a timeout-factor of 0 or less is used then just multiply by 1 (no timeout-factor).

yancyribbens commented at 11:39 AM on September 3, 2022: contributor

I think this would be a more clean approach: commit.

theStack commented at 9:59 PM on September 4, 2022: contributor

I feel like this is a mistake introduced by this PR. If a timeout-factor of 0 or less is used then just multiply by 1 (no timeout-factor).

I think this would be a more clean approach: commit.

This would change the semantics; the idea is that timeout-factor 0 disables RPC timeouts at all (or at least, simulate that they are disabled by just setting them to extremely high values), which is IMHO useful and should be kept:

https://github.com/bitcoin/bitcoin/blob/0ebd4db32b39cb7c505148f090df4b7ac778c307/test/README.md?plain=1#L275-L277

Also, it would still not resolve the issue for manually specified high values like e.g. timeout-factor 666666.

in test/functional/test_framework/authproxy.py:81 in e600b33397 outdated

  77 | @@ -78,7 +78,9 @@ def __init__(self, service_url, service_name=None, timeout=HTTP_TIMEOUT, connect
  78 |          passwd = None if self.__url.password is None else self.__url.password.encode('utf8')
  79 |          authpair = user + b':' + passwd
  80 |          self.__auth_header = b'Basic ' + base64.b64encode(authpair)
  81 | -        self.timeout = timeout
  82 | +        # larger values of the timeout cause an "Invalid argument"

Zero-1729 commented at 6:16 AM on September 5, 2022:

        # larger timeout values cause an "Invalid argument"

in test/functional/test_framework/authproxy.py:82 in e600b33397 outdated

  77 | @@ -78,7 +78,9 @@ def __init__(self, service_url, service_name=None, timeout=HTTP_TIMEOUT, connect
  78 |          passwd = None if self.__url.password is None else self.__url.password.encode('utf8')
  79 |          authpair = user + b':' + passwd
  80 |          self.__auth_header = b'Basic ' + base64.b64encode(authpair)
  81 | -        self.timeout = timeout
  82 | +        # larger values of the timeout cause an "Invalid argument"
  83 | +        # socket exception in Python's HTTP client library, so clamp it

Zero-1729 commented at 6:16 AM on September 5, 2022:

nit: Just to clarify what's being clamped, though the code is self-explanatory.

        # socket exception in Python's HTTP client library
        # to avoid this, we clamp the timeout value

Or something similar.

in test/functional/test_framework/authproxy.py:84 in e600b33397 outdated

  77 | @@ -78,7 +78,9 @@ def __init__(self, service_url, service_name=None, timeout=HTTP_TIMEOUT, connect
  78 |          passwd = None if self.__url.password is None else self.__url.password.encode('utf8')
  79 |          authpair = user + b':' + passwd
  80 |          self.__auth_header = b'Basic ' + base64.b64encode(authpair)
  81 | -        self.timeout = timeout
  82 | +        # larger values of the timeout cause an "Invalid argument"
  83 | +        # socket exception in Python's HTTP client library, so clamp it
  84 | +        self.timeout = min(timeout, 2147483)

Zero-1729 commented at 6:18 AM on September 5, 2022:

Out of curiosity, is there a reason you chose 2147483?

luke-jr commented at 1:41 AM on September 9, 2022:

That's the max 31-bit number, converted from milliseconds to seconds.

But this is assuming the OS has specific limitations. Not really a good fix.

Zero-1729 commented at 11:36 AM on September 17, 2022:

Got it, thanks Luke.

Zero-1729 commented at 6:26 AM on September 5, 2022: contributor

Concept ACK

This would change the semantics; the idea is that timeout-factor 0 disables RPC timeouts at all (or at least, simulate that they are disabled by just setting them to extremely high values), which is IMHO useful and should be kept:

Agree, the current clamp approach makes sense to maintain the intent of the timeout-factor.

Master (0ebd4db32b39cb7c505148f090df4b7ac778c307)

Note: I ran all local tests on macOS v12.5.1 (21G83) with Python 3.9.12.

I could not replicate this bug on macOS when I tested both test/functional/wallet_basic.py --timeout-factor 0 and test/functional/wallet_basic.py --timeout-factor 999999, as they both ran fine with no errors. However, I got the following error when I set the --timeout-factor to a much larger number 999999999:

❯ test/functional/wallet_basic.py --timeout-factor 999999999 
2022-09-05T05:40:46.607000Z TestFramework (INFO): Initializing test directory /var/folders/rx/jnjm6k8x3l3116w5vsslnmxr0000gn/T/bitcoin_func_test_mdyii8sm
2022-09-05T05:40:46.879000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/Users/abubakar/Github/bitcoin/test/functional/test_framework/test_framework.py", line 549, in start_nodes
    node.wait_for_rpc_connection()
  File "/Users/abubakar/Github/bitcoin/test/functional/test_framework/test_node.py", line 236, in wait_for_rpc_connection
    rpc.getblockcount()
...
  File "/opt/homebrew/Cellar/python@3.9/3.9.12/Frameworks/Python.framework/Versions/3.9/lib/python3.9/socket.py", line 829, in create_connection
    sock.settimeout(timeout)
OverflowError: timestamp too large to convert to C _PyTime_t

During handling of the above exception, another exception occurred:
...
AssertionError: [node 0] Error: no RPC connection
2022-09-05T05:40:46.978000Z TestFramework (INFO): Stopping nodes
...
AssertionError: [node 0] Error: no RPC connection
...

PR (e600b33397c749e6087762b0e25da57387ee69c9)

After this patch, the errors are no longer reported when I tested the --timeout-factor with 0, 999999, and 999999999.

❯ test/functional/wallet_basic.py --timeout-factor 999999999 
2022-09-05T05:40:48.862000Z TestFramework (INFO): Initializing test directory /var/folders/rx/jnjm6k8x3l3116w5vsslnmxr0000gn/T/bitcoin_func_test_mj62ey7e
2022-09-05T05:40:50.482000Z TestFramework (INFO): Mining blocks...
2022-09-05T05:40:51.571000Z TestFramework (INFO): Test gettxout
...
2022-09-05T05:41:09.478000Z TestFramework (INFO): Cleaning up /var/folders/rx/jnjm6k8x3l3116w5vsslnmxr0000gn/T/bitcoin_func_test_mj62ey7e on exit
2022-09-05T05:41:09.478000Z TestFramework (INFO): Tests successful

Although in your stack trace OSError is reported, given that I could replicate a similar error on macOS using the same Python version you had, I am not sure this is a platform-dependent error.

yancyribbens commented at 9:06 AM on September 5, 2022: contributor

or at least, simulate that they are disabled by just setting them to extremely high values

Ok, it seems odd to me that setting to extreme values is the same as setting the timeout to 0. Also, about 2147483 still works for me on FreeBSD, but 0 is too large and crashes.

Also, it would still not resolve the issue for manually specified high values like e.g. timeout-factor 666666.

That's true. I'm not sure how what the upper limit should be. Also your change still crashes if someone inputs a negate value like timeout-factor -1

luke-jr commented at 1:43 AM on September 9, 2022: member

What if you just change --timeout-factor to use None and pass that down properly?

DrahtBot commented at 4:42 AM on September 23, 2022: contributor

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Reviews

See the guideline for information on the review process.

Type	Reviewers
ACK	MarcoFalke
Concept ACK	Zero-1729

If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

Conflicts

No conflicts as of last run.

fanquake commented at 2:55 PM on February 17, 2023: member

Not clear what the status of this is. Looks like there are atleast some comments that need addressing?

test: fix test abort for high timeout values (and `--timeout-factor 0`) 14302a4802

theStack force-pushed on Feb 17, 2023

theStack commented at 10:54 PM on February 17, 2023: contributor

Force-pushed with an updated comment as per feedback from @Zero-1729, I hope the intent is more clear now to the reader.

What if you just change --timeout-factor to use None and pass that down properly? @luke-jr: The value specified via --timeout-factor is multiplied at several places in the test framework with a concrete number to calculate the actually used timeout (see e.g. git grep "* .*timeout_factor" ./test/functional/test_framework/), I don't see how using None here leads to anything useful (and even if, it would still only solve the --timeout-factor 0 case, not the one with higher numbers).

I still think the PR is the most straight-forward solution that fixes both calling a functional test with --timeout-factor 0 and a large number like --timeout-factor 9999999. The only drawback is that timeouts higher than ~3 weeks get clamped for operating systems that would support it, which seems to be not really relevant from a practical perspective.

fanquake requested review from maflcko on Feb 19, 2023

maflcko commented at 3:12 PM on February 20, 2023: member

lgtm ACK 14302a4802e2dbb41f5189de88f99ddd5dda7736

fanquake merged this on Feb 20, 2023

fanquake closed this on Feb 20, 2023

theStack deleted the branch on Feb 20, 2023

sidhujag referenced this in commit b70288215d on Feb 25, 2023

bitcoin locked this on Feb 20, 2024