interface_bitcoin_cli.py fails intermittently

[maflcko]

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

[maflcko]

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

[brakmic]

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

[jonatack]

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.

[brakmic]

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.

[brakmic]

@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.

[jonatack]

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.

[brakmic]

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?

[jonatack]

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())

[brakmic]

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.