interface_bitcoin_cli.py fails intermittently #18684

https://travis-ci.org/github/bitcoin/bitcoin/jobs/676156661#L6349

 test  2020-04-17T14:09:31.865000Z TestFramework (ERROR): 
  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) 

cc @jonatack

The failure is in the line with -rpcwait, you probably need wait_for_rpc_connection

Same problem with my PR: https://travis-ci.org/github/bitcoin/bitcoin/jobs/676136137

Same problem with my PR: https://travis-ci.org/github/bitcoin/bitcoin/jobs/676136137

Are you able to reproduce locally? Even valgrind test/functional/interface_bitcoin_cli.py -l debug runs fine for me.

Same problem with my PR: https://travis-ci.org/github/bitcoin/bitcoin/jobs/676136137

Are you able to reproduce locally?

Sadly, I'm not. All test pass, no errors whatsoever.

@jonatack

However, there's one thing I just did that provoked the same error:

I changed setup_clean_chain to False.

self.setup_clean_chain = False

Then I got this:

./test/functional/interface_bitcoin_cli.py                                          (3s 428ms)  
2020-04-17T16:59:26.097000Z TestFramework (INFO): Initializing test directory /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_6h67eta3
2020-04-17T16:59:28.940000Z TestFramework (INFO): Compare responses from getwalletinfo RPC and `bitcoin-cli getwalletinfo`
2020-04-17T16:59:29.002000Z TestFramework (INFO): Compare responses from getblockchaininfo RPC and `bitcoin-cli getblockchaininfo`
2020-04-17T16:59:29.024000Z TestFramework (INFO): Test -stdinrpcpass option
2020-04-17T16:59:29.043000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/Users/brakmic/projects/bitcoin-dev/btc-global-ctx/test/functional/test_framework/test_framework.py", line 112, in main
    self.run_test()
  File "./test/functional/interface_bitcoin_cli.py", line 45, in run_test
    assert_equal(BLOCKS, self.nodes[0].cli('-rpcuser=%s' % user, '-stdinrpcpass', input=password).getblockcount())
  File "/Users/brakmic/projects/bitcoin-dev/btc-global-ctx/test/functional/test_framework/util.py", line 46, in assert_equal
    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
AssertionError: not(101 == 301)
2020-04-17T16:59:29.123000Z TestFramework (INFO): Stopping nodes
2020-04-17T16:59:29.584000Z TestFramework (WARNING): Not cleaning up dir /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_6h67eta3
2020-04-17T16:59:29.585000Z TestFramework (ERROR): Test failed. Test logging available at /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_6h67eta3/test_framework.log
2020-04-17T16:59:29.586000Z TestFramework (ERROR): Hint: Call /Users/brakmic/projects/bitcoin-dev/btc-global-ctx/test/functional/combine_logs.py '/var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_6h67eta3' to consolidate all logs

Which could mean that this fails when it runs on a touched chain.

--EDIT: forgot to mention that this is only a speculation of mine.

The issue isn't from running too slowly: I added timeouts of up to 90 seconds before and after the call and the test doesn't fail.

         # Verify failure without -rpcwait.
         assert_raises_process_error(1, "Could not connect to the server", self.nodes[0].cli('getblockcount').echo)
         # Verify success using -rpcwait.
+        import time; time.sleep(90)
         assert_equal(BLOCKS, self.nodes[0].cli('-rpcwait', 'getblockcount').send_cli())
+        time.sleep(90)
         self.nodes[0].wait_for_rpc_connection()

AFAICT it's failing because failedToGetAuthCookie is set to true at bitcoin-cli.cpp::L352 and triggering the throw at bitcoin-cli.cpp::L398.

The issue isn't from running too slowly: I added timeouts of up to 90 seconds before and after the call and the test doesn't fail.

         # Verify failure without -rpcwait.
         assert_raises_process_error(1, "Could not connect to the server", self.nodes[0].cli('getblockcount').echo)
         # Verify success using -rpcwait.
+        import time; time.sleep(90)
         assert_equal(BLOCKS, self.nodes[0].cli('-rpcwait', 'getblockcount').send_cli())
+        time.sleep(90)
         self.nodes[0].wait_for_rpc_connection()

AFAICT it's failing because failedToGetAuthCookie is set to true at bitcoin-cli.cpp::L352 and triggering the throw at bitcoin-cli.cpp::L398.

Interesting!

Maybe in future, if my PR regarding factor option for timeouts gets accepted, we could add such an option for this test as well?

Tempted to propose something like this, as I can't reproduce the failure locally:

         # Verify success using -rpcwait.
+        time.sleep(1)
         assert_equal(BLOCKS, self.nodes[0].cli('-rpcwait', 'getblockcount').send_cli())

Tempted to propose something like this, as I can't reproduce the failure locally:

         # Verify success using -rpcwait.
+        time.sleep(1)
         assert_equal(BLOCKS, self.nodes[0].cli('-rpcwait', 'getblockcount').send_cli())

Well, I am not a python expert, but wouldn't be better to have some kind of async/wait or JS-like promise function (not sure what's the proper, pythonic way of doing such things). thread.sleep feels kinda hard, like a stop sign.