test: add wait_for_cookie_credentials() to framework for rpcwait tests

jonatack commented at 8:37 pm on April 17, 2020: member

This PR adds a wait_for_cookie_credentials() method to the test framework and calls it before the -rpcwait tests, to avoid an intermittent race condition on the CI run with Valgrind where the cookie file isn’t written yet when the CLI call with -rpcwait arrives to get_auth_cookie().

To reproduce/test, build with

0diff --git a/src/httprpc.cpp b/src/httprpc.cpp
1index 60c4d06f12..3dd06c4758 100644
2--- a/src/httprpc.cpp
3+++ b/src/httprpc.cpp
4@@ -291,6 +291,7 @@ static bool InitRPCAuthentication()
5 bool StartHTTPRPC()
6 {
7     LogPrint(BCLog::RPC, "Starting HTTP RPC server\n");
8+    UninterruptibleSleep(std::chrono::seconds{11});
9     if (!InitRPCAuthentication())

then run the test normally and with valgrind

0test/functional/interface_bitcoin_cli.py -l debug
1valgrind test/functional/interface_bitcoin_cli.py -l debug

Thanks to Marco Falke for all the help. Closes #18684.

MarcoFalke commented at 8:45 pm on April 17, 2020: member

The error was " Called Process failed with ’error: Could not locate RPC credentials. No authentication cookie could be found, and RPC password is not set. See -rpcpassword and -stdinrpcpass. Configuration file: (/home/travis/build/bitcoin/bitcoin/ci/scratch/test_runner/test_runner_₿_🏃_20200417_132645/interface_bitcoin_cli_109/node0/bitcoin.conf) "

jonatack commented at 8:53 pm on April 17, 2020: member

Yes. I’m still looking at it, but since valgrind runs don’t work out-of-repo, I wanted to see if the valgrind CI passes with this change while looking further.

MarcoFalke commented at 9:08 pm on April 17, 2020: member

get_auth_cookie is used by every single test. It reads the auth cookie from disk, though it fails when the file was not yet created.

DrahtBot added the label Tests on Apr 17, 2020

DrahtBot commented at 10:54 pm on April 17, 2020: member

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

Conflicts

Reviewers, this pull request conflicts with the following ones:

#18594 (cli: display multiwallet balances in -getinfo by jonatack)
#18453 (rpc, cli: add multiwallet balances rpc and use it in -getinfo by jonatack)

If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

jonatack renamed this:
~~test: fix intermittent error in interface_bitcoin_cli~~
test: add wait_for_cookie_credentials() to framework, improve rpcwait tests
on Apr 18, 2020

jonatack renamed this:
~~test: add wait_for_cookie_credentials() to framework, improve rpcwait tests~~
test: add wait_for_cookie_credentials() to framework for rpcwait tests
on Apr 18, 2020

jonatack force-pushed on Apr 18, 2020

MarcoFalke commented at 3:39 pm on April 18, 2020: member

Btw, this happens on cirrus reliably: https://cirrus-ci.com/task/6597545033990144?command=functional_test#L1053

MarcoFalke commented at 3:42 pm on April 18, 2020: member

Or, if you want to test locally:

 0diff --git a/src/httprpc.cpp b/src/httprpc.cpp
 1index 60c4d06f12..3dd06c4758 100644
 2--- a/src/httprpc.cpp
 3+++ b/src/httprpc.cpp
 4@@ -291,6 +291,7 @@ static bool InitRPCAuthentication()
 5 bool StartHTTPRPC()
 6 {
 7     LogPrint(BCLog::RPC, "Starting HTTP RPC server\n");
 8+    UninterruptibleSleep(std::chrono::seconds{11});
 9     if (!InitRPCAuthentication())
10         return false;
11

jonatack force-pushed on Apr 18, 2020

jonatack commented at 4:54 pm on April 18, 2020: member

Thanks @MarcoFalke for your suggestions! Being able to reproduce makes all the difference. I updated the PR title and description and pushed a fix that seems to work.

jonatack force-pushed on Apr 18, 2020

in test/functional/test_framework/util.py:357 in 72a079e398 outdated

353@@ -354,7 +354,7 @@ def get_auth_cookie(datadir, chain):
354             password = split_userpass[1]
355     except OSError:
356         pass
357-    if user is None or password is None:
358+    if (user is None or password is None) and wait_for_cookie is False:

MarcoFalke commented at 5:06 pm on April 18, 2020:

I don’t really like offering two interfaces. The existing one that either returns an auth pair or thorws a ValueError should be sufficient.

If you don’t like the generic ValueError, I believe python can create derived classes like this RpcCredentialsMissing(ValueError), which you can then throw/catch.

jonatack commented at 7:15 pm on April 18, 2020:

Thanks for reviewing and your help. If I understand your comment correctly, I modified the conditional here not to change the interface, but to not raise when we’re waiting for the cookie auth credentials. When they do become available, it still returns the auth pair which we’re waiting for in wait_for_cookie_credentials().

jonatack commented at 7:17 pm on April 18, 2020:

E.g. since wait_for_cookie is false by default, there is no change in behavior except when it’s called by wait_for_cookie_credentials.

MarcoFalke commented at 7:36 pm on April 18, 2020:

Yeah, I don’t understand why wait_for_cookie is needed? Just because it is turned off by default doesn’t mean that it doesn’t complicate the interface

jonatack commented at 7:42 pm on April 18, 2020:

Hm, maybe it isn’t. Good question.

MarcoFalke commented at 7:47 pm on April 18, 2020:

They should never be empty.

Either both are a string of length of at least 1 or a ValueError is thrown

jonatack commented at 8:06 pm on April 18, 2020:

Good catch, fixed.

jonatack commented at 6:44 pm on April 18, 2020: member

I see that the CI for the latest merge on master (bump wallet_import timeout) failed for this same reason: https://travis-ci.org/github/bitcoin/bitcoin/jobs/676639823

MarcoFalke approved

jonatack force-pushed on Apr 18, 2020

jonatack commented at 8:17 pm on April 18, 2020: member

Simplified.

Edit: FWIW I considered adding the following but don’t think it’s necessary? IIUC wait_for_cookie_credentials shouldn’t see any other type of ValueError, nor ECONNREFUSED.

0+            except OSError as e:
1+                if e.errno != errno.ECONNREFUSED:  # Port not yet open?
2+                    raise  # Unknown OS error
3-            except ValueError:
4-                pass
5+            except ValueError as e:  # Cookie file not found and no rpcuser or rpcassword; bitcoind still starting.
6+                if "No RPC credentials" not in str(e):
7+                    raise

in test/functional/test_framework/test_node.py:259 in 83b037921f outdated

254+                self.log.debug("Cookie credentials retrieved: user={}, passphrase={}".format(user, passphrase))
255+                return
256+            except ValueError:
257+                pass
258+            time.sleep(1.0 / poll_per_s)
259+        self._raise_assertion_error("Unable to retrieve cookie credentials")

MarcoFalke commented at 10:42 pm on April 18, 2020:

nit: Could rebase and adjust the error to mention the timeout (like the one above, which you can see after rebase)

jonatack commented at 11:18 pm on April 18, 2020:

good idea; done

in test/functional/test_framework/test_node.py:254 in 83b037921f outdated

249+        # Poll at a rate of four times per second
250+        poll_per_s = 4
251+        for _ in range(poll_per_s * self.rpc_timeout):
252+            try:
253+                user, passphrase = get_auth_cookie(self.datadir, self.chain)
254+                self.log.debug("Cookie credentials retrieved: user={}, passphrase={}".format(user, passphrase))

MarcoFalke commented at 10:43 pm on April 18, 2020:

nit: the values aren’t needed, only their presence, so no need to log them?

jonatack commented at 11:18 pm on April 18, 2020:

done

in test/functional/test_framework/test_node.py:256 in 83b037921f outdated

251+        for _ in range(poll_per_s * self.rpc_timeout):
252+            try:
253+                user, passphrase = get_auth_cookie(self.datadir, self.chain)
254+                self.log.debug("Cookie credentials retrieved: user={}, passphrase={}".format(user, passphrase))
255+                return
256+            except ValueError:

MarcoFalke commented at 10:44 pm on April 18, 2020:

nit: In a future cleanup the three occurrences of ValueError can be changed to a self-made error RpcMissingCred (or so). Not asking you to do this here.

jonatack commented at 11:22 pm on April 18, 2020:

nit: In a future cleanup the three occurrences of ValueError can be changed to a self-made error RpcMissingCred (or so). Not asking you to do this here.

Good idea. Will look at a follow-up.

MarcoFalke approved

MarcoFalke commented at 10:44 pm on April 18, 2020: member

ACK 83b037921fac34d4c85ce6a2e137407596fed91e

Happy to merge with or without feedback addressed. Just let me know what you prefer.

jonatack force-pushed on Apr 18, 2020

jonatack commented at 11:25 pm on April 18, 2020: member

Took the suggestions.

jonatack force-pushed on Apr 18, 2020

MarcoFalke approved

DrahtBot added the label Needs rebase on Apr 19, 2020

test: add wait_for_cookie_credentials() to test framework

to be able to ensure the cookie file is written and auth credentials available
when testing CLI/RPC commands before the RPC connection is up.

c648e636b2

test: fix intermittent race condition in interface_bitcoin_cli.py

by calling wait_for_cookie_credentials() to ensure the cookie file is written
and auth credentials available for testing the CLI -rpcwait option before the
RPC connection is up.

92fe537cf7

jonatack force-pushed on Apr 19, 2020

DrahtBot removed the label Needs rebase on Apr 19, 2020

jonatack commented at 1:16 am on April 20, 2020: member

Rebased and added a docstring to wait_for_cookie_credentials().

in test/functional/interface_bitcoin_cli.py:80 in 92fe537cf7

74@@ -76,20 +75,17 @@ def run_test(self):
75         else:
76             self.log.info("*** Wallet not compiled; cli getwalletinfo and -getinfo wallet tests skipped")
77 
78-        self.stop_node(0)
79-
80         self.log.info("Test -version with node stopped")
81-        cli_response = self.nodes[0].cli("-version").send_cli()
82+        self.stop_node(0)
83+        cli_response = self.nodes[0].cli().send_cli('-version')

MarcoFalke commented at 10:08 am on April 20, 2020:

Why is this changed?

MarcoFalke commented at 10:19 am on April 20, 2020:

-version is not an rpc command, but a command line option

MarcoFalke merged this on Apr 20, 2020

MarcoFalke closed this on Apr 20, 2020

in test/functional/interface_bitcoin_cli.py:54 in 92fe537cf7

50@@ -52,7 +51,7 @@ def run_test(self):
51         self.log.info("Test -getinfo returns expected network and blockchain info")
52         if self.is_wallet_compiled():
53             self.nodes[0].encryptwallet(password)
54-        cli_get_info = self.nodes[0].cli('-getinfo').send_cli()
55+        cli_get_info = self.nodes[0].cli().send_cli('-getinfo')

MarcoFalke commented at 10:19 am on April 20, 2020:

same here

jonatack commented at 1:20 pm on April 20, 2020:

I changed it to improve the debug log output:

0- TestFramework.bitcoincli (DEBUG): Running bitcoin-cli command: None
1+ TestFramework.bitcoincli (DEBUG): Running bitcoin-cli command: -getinfo
2
3- TestFramework.bitcoincli (DEBUG): Running bitcoin-cli command: None
4+ TestFramework.bitcoincli (DEBUG): Running bitcoin-cli command: -version

I can revert it in #18594 that also touches the testfile or look at improving the logging output for these cases.

MarcoFalke commented at 1:36 pm on April 20, 2020:

That should be fixed by logging the options, not passing the command line option as the rpc command

jonatack commented at 9:38 pm on April 20, 2020:

That should be fixed by logging the options, not passing the command line option as the rpc command

Done in #18712.

jonatack deleted the branch on Apr 20, 2020

sidhujag referenced this in commit 767b73a827 on Apr 20, 2020

MarcoFalke referenced this in commit d1aa0ae1ad on Apr 24, 2020

sidhujag referenced this in commit 074dad0954 on Apr 24, 2020

luke-jr referenced this in commit d457d73d2b on Jun 14, 2020

luke-jr referenced this in commit e9839454fa on Jun 14, 2020

Fabcien referenced this in commit bd45ab5e8e on Jan 26, 2021

DrahtBot locked this on Feb 15, 2022

test: add wait_for_cookie_credentials() to framework for rpcwait tests #18691

Conflicts