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

jonatack · 2020-04-17T20:37:33Z

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

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

then run the test normally and with valgrind

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

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

maflcko · 2020-04-17T20:45:07Z

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 · 2020-04-17T20:53:40Z

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.

maflcko · 2020-04-17T21:08:43Z

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 · 2020-04-17T22:54:13Z

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

Conflicts

Reviewers, this pull request conflicts with the following ones:

cli: display multiwallet balances in -getinfo #18594 (cli: display multiwallet balances in -getinfo by jonatack)
rpc, cli: add multiwallet balances rpc and use it in -getinfo #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.

maflcko · 2020-04-18T15:39:34Z

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

maflcko · 2020-04-18T15:42:47Z

Or, if you want to test locally:

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

jonatack · 2020-04-18T16:54:27Z

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 · 2020-04-18T18:44:28Z

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

test/functional/test_framework/util.py

jonatack · 2020-04-18T20:17:11Z

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.

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

maflcko

ACK 83b0379

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

test/functional/test_framework/test_node.py

maflcko · 2020-04-18T22:44:08Z

test/functional/test_framework/test_node.py

+                user, passphrase = get_auth_cookie(self.datadir, self.chain)
+                self.log.debug("Cookie credentials retrieved: user={}, passphrase={}".format(user, passphrase))
+                return
+            except ValueError:


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.

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.

jonatack · 2020-04-18T23:25:03Z

Took the suggestions.

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.

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.

jonatack · 2020-04-20T01:16:57Z

Rebased and added a docstring to wait_for_cookie_credentials().

test/functional/interface_bitcoin_cli.py

…work for rpcwait tests 92fe537 test: fix intermittent race condition in interface_bitcoin_cli.py (Jon Atack) c648e63 test: add wait_for_cookie_credentials() to test framework (Jon Atack) Pull request description: 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 ```diff diff --git a/src/httprpc.cpp b/src/httprpc.cpp index 60c4d06..3dd06c4758 100644 --- a/src/httprpc.cpp +++ b/src/httprpc.cpp @@ -291,6 +291,7 @@ static bool InitRPCAuthentication() bool StartHTTPRPC() { LogPrint(BCLog::RPC, "Starting HTTP RPC server\n"); + UninterruptibleSleep(std::chrono::seconds{11}); if (!InitRPCAuthentication()) ``` then run the test normally and with valgrind ``` test/functional/interface_bitcoin_cli.py -l debug valgrind test/functional/interface_bitcoin_cli.py -l debug ``` Thanks to Marco Falke for all the help. Closes bitcoin#18684. Top commit has no ACKs. Tree-SHA512: 1b76635b5b1d6b05138affef7ab788aa3bc3fc75b0c69ba778ecdf81063cfe02a8dd7667cfd63a6c6e19b2dac47d7a8b755e334d8af5c0ab9d4026808ee96c83

…d_cli() in debug log 8f5dc88 test: display command line options passed to send_cli() in debug log (Jon Atack) Pull request description: as per bitcoin#18691 (comment), and revert two cli calls changed in bitcoin#18691 from rpc commands back to command line options (these were the only occurrences). ACKs for top commit: MarcoFalke: ACK 8f5dc88 Tree-SHA512: fcb3eca00aa4099066028c90d5e50a02e074366e09a17f5f5b937d9f7562dd054ff65681aa0ad4c94f6de1e98b1e2b9ac4cd084ddc297010253989a80483b1b9

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. Github-Pull: bitcoin#18691 Rebased-From: c648e63

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. Github-Pull: bitcoin#18691 Rebased-From: 92fe537

Summary: > 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. > 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. This is a backport of Core [[bitcoin/bitcoin#18691 | PR18691]] Test Plan: ``` diff --git a/src/httprpc.cpp b/src/httprpc.cpp index 9e09af5..8301f8cd1 100644 --- a/src/httprpc.cpp +++ b/src/httprpc.cpp @@ -453,6 +453,7 @@ static bool InitRPCAuthentication() { bool StartHTTPRPC(HTTPRPCRequestProcessor &httpRPCRequestProcessor) { LogPrint(BCLog::RPC, "Starting HTTP RPC server\n"); + UninterruptibleSleep(std::chrono::seconds{11}); if (!InitRPCAuthentication()) { return false; } ``` `ninja && test/functional/test_runner.py interface_bitcoin_cli` Reviewers: #bitcoin_abc, deadalnix, Fabien Reviewed By: #bitcoin_abc, deadalnix, Fabien Subscribers: Fabien, deadalnix Differential Revision: https://reviews.bitcoinabc.org/D8947

DrahtBot added the Tests label Apr 17, 2020

This was referenced Apr 17, 2020

cli: display multiwallet balances in -getinfo #18594

Merged

rpc, cli: add multiwallet balances rpc and use it in -getinfo #18453

Closed

jonatack changed the title ~~test: fix intermittent error in interface_bitcoin_cli~~ test: add wait_for_cookie_credentials() to framework, improve rpcwait tests Apr 18, 2020

jonatack changed the title ~~test: add wait_for_cookie_credentials() to framework, improve rpcwait tests~~ test: add wait_for_cookie_credentials() to framework for rpcwait tests Apr 18, 2020

jonatack force-pushed the fix-intermittent-credentials-issue branch from 8854851 to b726718 Compare April 18, 2020 15:25

jonatack force-pushed the fix-intermittent-credentials-issue branch from b726718 to ecafe40 Compare April 18, 2020 16:48

jonatack force-pushed the fix-intermittent-credentials-issue branch from ecafe40 to 72a079e Compare April 18, 2020 17:03

maflcko approved these changes Apr 18, 2020

View reviewed changes

test/functional/test_framework/util.py Outdated Show resolved Hide resolved

jonatack force-pushed the fix-intermittent-credentials-issue branch 2 times, most recently from 5c7e759 to 83b0379 Compare April 18, 2020 20:15

maflcko approved these changes Apr 18, 2020

View reviewed changes

jonatack force-pushed the fix-intermittent-credentials-issue branch from 83b0379 to e67a1e2 Compare April 18, 2020 23:18

jonatack force-pushed the fix-intermittent-credentials-issue branch from e67a1e2 to 790fb95 Compare April 18, 2020 23:38

DrahtBot mentioned this pull request Apr 19, 2020

test: Properly raise FailedToStartError when rpc shutdown before warmup finished (take 2) #18633

Merged

maflcko approved these changes Apr 19, 2020

View reviewed changes

DrahtBot added the Needs rebase label Apr 19, 2020

jonatack added 2 commits April 19, 2020 18:12

test: add wait_for_cookie_credentials() to test framework

c648e63

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.

test: fix intermittent race condition in interface_bitcoin_cli.py

92fe537

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.

jonatack force-pushed the fix-intermittent-credentials-issue branch from 790fb95 to 92fe537 Compare April 19, 2020 16:23

DrahtBot removed the Needs rebase label Apr 19, 2020

maflcko reviewed Apr 20, 2020

View reviewed changes

test/functional/interface_bitcoin_cli.py Show resolved Hide resolved

maflcko merged commit dc5da7f into bitcoin:master Apr 20, 2020

maflcko reviewed Apr 20, 2020

View reviewed changes

test/functional/interface_bitcoin_cli.py Show resolved Hide resolved

dongcarl mentioned this pull request Apr 20, 2020

build: fix ASLR for bitcoin-cli on Windows #18702

Merged

jonatack deleted the fix-intermittent-credentials-issue branch April 20, 2020 13:15

jonatack mentioned this pull request Apr 20, 2020

test: display command line options passed to send_cli() in debug log #18712

Merged

bitcoin locked as resolved and limited conversation to collaborators Feb 15, 2022

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

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

Uh oh!

Conversation

jonatack commented Apr 17, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

maflcko commented Apr 17, 2020

Uh oh!

jonatack commented Apr 17, 2020

Uh oh!

maflcko commented Apr 17, 2020

Uh oh!

DrahtBot commented Apr 17, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Conflicts

Uh oh!

maflcko commented Apr 18, 2020

Uh oh!

maflcko commented Apr 18, 2020

Uh oh!

jonatack commented Apr 18, 2020

Uh oh!

jonatack commented Apr 18, 2020

Uh oh!

Uh oh!

jonatack commented Apr 18, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

maflcko left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

maflcko Apr 18, 2020

Choose a reason for hiding this comment

Uh oh!

jonatack Apr 18, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jonatack commented Apr 18, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jonatack commented Apr 20, 2020

Uh oh!

Uh oh!

Uh oh!

Uh oh!

jonatack commented Apr 17, 2020 •

edited

Loading

DrahtBot commented Apr 17, 2020 •

edited

Loading

jonatack commented Apr 18, 2020 •

edited

Loading

maflcko left a comment •

edited

Loading

jonatack Apr 18, 2020 •

edited

Loading

jonatack commented Apr 18, 2020 •

edited

Loading