pytests reading ~/.bitcoin/bitcoin.conf ???

[SimonVrouwe]

Issue and Steps to Reproduce

Running make full-check on locally build rc2 10f47b41fa with Bitcoin Core version v0.19.1 on keeps failing on test_closing (and probably other tests also). Changing test parameters like (SLOW_MACHINE=1, TIMEOUT=360 etc.), didn't solve it.

But renaming my ~/.bitcoin/bitcoin.conf file makes the test pass!

When running the individual test with: DEVELOPER=1 PYTHONPATH=contrib/pylightning:contrib/pyln-client:contrib/pyln-testing:contrib/pyln-proto py.test -v -s tests/test_closing.py::test_closing with an ipdb break point just above https://github.com/ElementsProject/lightning/blob/10f47b41fa3192638442ef04d816380950cc32c9/tests/test_closing.py#L19 to get the PID

Then running strace to monitor file access to ~/.bitcoin/bitcoin.conf: strace -e trace=/stat -q -P /home/simon/.bitcoin/ -f -y -k -p 8471 (8471 is PID of above pytest) and hit continue from breakpoint, shows two calls: stat("/home/simon/.bitcoin" ,see:

[pid  8608] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=8633, si_uid=1000, si_status=0, si_utime=138, si_stime=12} ---
 > /usr/lib/x86_64-linux-gnu/valgrind/memcheck-amd64-linux() [0xf5c6e]
[pid  8640] stat("/home/simon/.bitcoin", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
 > /usr/lib/x86_64-linux-gnu/libc-2.28.so(__xstat64+0x15) [0xe9aa5]
 > /usr/lib/x86_64-linux-gnu/libboost_filesystem.so.1.67.0(boost::filesystem::detail::status(boost::filesystem::path const&, boost::system::error_code*)+0x3d) [0xc1bd]
 > /usr/lib/x86_64-linux-gnu/libboost_filesystem.so.1.67.0(boost::filesystem::detail::create_directories(boost::filesystem::path const&, boost::system::error_code*)+0xde) [0xc68e]
 > /usr/local/bin/bitcoin-cli(GetDataDir(bool)+0x1ec) [0x3ffcc]
 > /usr/local/bin/bitcoin-cli(AbsPathForConfigVal(boost::filesystem::path const&, bool)+0x99) [0x40219]
 > /usr/local/bin/bitcoin-cli(GetConfigFile(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)+0x46) [0x40276]
 > /usr/local/bin/bitcoin-cli(ArgsManager::ReadConfigFiles(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&, bool)+0x137) [0x42e87]
 > /usr/local/bin/bitcoin-cli(AppInitRPC(int, char**)+0x24a1) [0x20521]
 > /usr/local/bin/bitcoin-cli(main+0x3f) [0x1838f]
 > /usr/lib/x86_64-linux-gnu/libc-2.28.so(__libc_start_main+0xeb) [0x2409b]
 > /usr/local/bin/bitcoin-cli(_start+0x2a) [0x1afda]
[pid  8641] stat("/home/simon/.bitcoin", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
 > /usr/lib/x86_64-linux-gnu/libc-2.28.so(__xstat64+0x15) [0xe9aa5]
 > /usr/lib/x86_64-linux-gnu/libboost_filesystem.so.1.67.0(boost::filesystem::detail::status(boost::filesystem::path const&, boost::system::error_code*)+0x3d) [0xc1bd]
 > /usr/lib/x86_64-linux-gnu/libboost_filesystem.so.1.67.0(boost::filesystem::detail::create_directories(boost::filesystem::path const&, boost::system::error_code*)+0xde) [0xc68e]
 > /usr/local/bin/bitcoin-cli(GetDataDir(bool)+0x1ec) [0x3ffcc]
 > /usr/local/bin/bitcoin-cli(AbsPathForConfigVal(boost::filesystem::path const&, bool)+0x99) [0x40219]
 > /usr/local/bin/bitcoin-cli(GetConfigFile(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)+0x46) [0x40276]
 > /usr/local/bin/bitcoin-cli(ArgsManager::ReadConfigFiles(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&, bool)+0x137) [0x42e87]
 > /usr/local/bin/bitcoin-cli(AppInitRPC(int, char**)+0x24a1) [0x20521]
 > /usr/local/bin/bitcoin-cli(main+0x3f) [0x1838f]
 > /usr/lib/x86_64-linux-gnu/libc-2.28.so(__libc_start_main+0xeb) [0x2409b]
 > /usr/local/bin/bitcoin-cli(_start+0x2a) [0x1afda]
[pid  8599] --- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=0x1ffeffcd08} ---
 > unexpected_backtracing_error [0x100458ed8e]

Besides failing the test, it doesn't sound good that the test looks for local bitcoin.conf with can contain password etc. Maybe bitcoin-cli is called somewhere without the -conf=<file> option?

A stat system call doesn't really read the file content, but failure/success of the test appears (checked manually) to depend on the presence of option rpcconnect in the bitcoin.conf

Will investigate further, perhaps I just messed up my setup, but thought I post this here already.

BTW here is the failing test log:

imon@gamepc:~/git/SimonVrouwe/lightning$ DEVELOPER=1 PYTHONPATH=contrib/pylightning:contrib/pyln-client:contrib/pyln-testing:contrib/pyln-proto py.test -v -s tests/test_closing.py::test_closing
============================================================================================================================== test session starts ===============================================================================================================================
platform linux -- Python 3.7.3, pytest-5.3.1, py-1.8.0, pluggy-0.12.0 -- /usr/bin/python3
cachedir: .pytest_cache
benchmark: 3.2.2 (defaults: timer=time.perf_counter disable_gc=False min_rounds=5 min_time=0.000005 max_time=1.0 calibration_precision=10 warmup=False warmup_iterations=100000)
rootdir: /home/simon/git/SimonVrouwe/lightning
plugins: xdist-1.29.0, benchmark-3.2.2, flaky-3.6.1, timeout-1.3.3, test-groups-1.0.3, forked-1.0.2
collected 1 item                                                                                                                                                                                                                                                                 

tests/test_closing.py::test_closing Running tests in /tmp/ltests-c36k78xd
Timed out while waiting for (one of) the Bitcoin backend plugin(s) to complete the handshake.
Timed out while waiting for (one of) the Bitcoin backend plugin(s) to complete the handshake.
FAILED
tests/test_closing.py::test_closing ERROR

===================================================================================================================================== ERRORS =====================================================================================================================================
_______________________________________________________________________________________________________________________ ERROR at teardown of test_closing ________________________________________________________________________________________________________________________

request = <SubRequest 'teardown_checks' for <Function test_closing>>

    @pytest.fixture
    def teardown_checks(request):
        """A simple fixture to collect errors during teardown.

        We need to collect the errors and raise them as the very last step in the
        fixture tree, otherwise some fixtures may not be cleaned up
        correctly. Require this fixture in all other fixtures that need to either
        cleanup before reporting an error or want to add an error that is to be
        reported.

        """
        errors = TeardownErrors()
        yield errors

        if errors.has_errors():
            # Format a nice list of everything that went wrong and raise an exception
            request.node.has_errors = True
>           raise ValueError(str(errors))
E           ValueError: 
E           Node errors:
E            - lightningd-2: Node exited with return code 1
E            - lightningd-1: Node exited with return code 1
E           Global errors:

contrib/pyln-testing/pyln/testing/fixtures.py:171: ValueError
==================================================================================================================================== FAILURES ====================================================================================================================================
__________________________________________________________________________________________________________________________________ test_closing __________________________________________________________________________________________________________________________________

node_factory = <pyln.testing.utils.NodeFactory object at 0x7fcd85a82320>, bitcoind = <pyln.testing.utils.BitcoinD object at 0x7fcd85ac50f0>
chainparams = {'bip173_prefix': 'bcrt', 'chain_hash': '06226e46111a0b59caaf126043eb5bbf28c34f3a5e332a1fc7b2b73cf188910f', 'elements': False, 'example_addr': 'bcrt1qeyyk6sl5pr49ycpqyckvmttus5ttj25pd0zpvg', ...}

    @unittest.skipIf(not DEVELOPER, "Too slow without --dev-bitcoind-poll")
    def test_closing(node_factory, bitcoind, chainparams):
    #     import ipdb; ipdb.set_trace()
>       l1, l2 = node_factory.line_graph(2)

tests/test_closing.py:20: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
contrib/pyln-testing/pyln/testing/utils.py:1067: in line_graph
    nodes = self.get_nodes(num_nodes, opts=opts)
contrib/pyln-testing/pyln/testing/utils.py:1014: in get_nodes
    return [j.result() for j in jobs]
contrib/pyln-testing/pyln/testing/utils.py:1014: in <listcomp>
    return [j.result() for j in jobs]
/usr/lib/python3.7/concurrent/futures/_base.py:432: in result
    return self.__get_result()
/usr/lib/python3.7/concurrent/futures/_base.py:384: in __get_result
    raise self._exception
/usr/lib/python3.7/concurrent/futures/thread.py:57: in run
    result = self.fn(*self.args, **self.kwargs)
contrib/pyln-testing/pyln/testing/utils.py:1055: in get_node
    node.start(wait_for_bitcoind_sync, stderr=stderr)
contrib/pyln-testing/pyln/testing/utils.py:658: in start
    self.daemon.start(stderr=stderr)
contrib/pyln-testing/pyln/testing/utils.py:535: in start
    self.wait_for_log("Server started with public key")
contrib/pyln-testing/pyln/testing/utils.py:287: in wait_for_log
    return self.wait_for_logs([regex], timeout)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <pyln.testing.utils.LightningD object at 0x7fcd85241c18>, regexs = ['Server started with public key'], timeout = 60

    def wait_for_logs(self, regexs, timeout=TIMEOUT):
        """Look for `regexs` in the logs.

        We tail the stdout of the process and look for each regex in `regexs`,
        starting from last of the previous waited-for log entries (if any).  We
        fail if the timeout is exceeded or if the underlying process
        exits before all the `regexs` were found.

        If timeout is None, no time-out is applied.
        """
        logging.debug("Waiting for {} in the logs".format(regexs))
        exs = [re.compile(r) for r in regexs]
        start_time = time.time()
        pos = self.logsearch_start
        while True:
            if timeout is not None and time.time() > start_time + timeout:
                print("Time-out: can't find {} in logs".format(exs))
                for r in exs:
                    if self.is_in_log(r):
                        print("({} was previously in logs!)".format(r))
                raise TimeoutError('Unable to find "{}" in logs.'.format(exs))
            elif not self.running:
>               raise ValueError('Process died while waiting for logs')
E               ValueError: Process died while waiting for logs

contrib/pyln-testing/pyln/testing/utils.py:265: ValueError
================================================================================================================================ warnings summary ================================================================================================================================
/home/simon/.local/lib/python3.7/site-packages/jinja2/utils.py:485
  /home/simon/.local/lib/python3.7/site-packages/jinja2/utils.py:485: DeprecationWarning: Using or importing the ABCs from 'collections' instead of from 'collections.abc' is deprecated, and in 3.8 it will stop working
    from collections import MutableMapping

/home/simon/.local/lib/python3.7/site-packages/jinja2/runtime.py:318
  /home/simon/.local/lib/python3.7/site-packages/jinja2/runtime.py:318: DeprecationWarning: Using or importing the ABCs from 'collections' instead of from 'collections.abc' is deprecated, and in 3.8 it will stop working
    from collections import Mapping

-- Docs: https://docs.pytest.org/en/latest/warnings.html
==================================================================================================================== 1 failed, 2 warnings, 1 error in 56.06s =====================================================================================================================
simon@gamepc:~/git/SimonVrouwe/lightning$ bcli: 
Could not connect to bitcoind using bitcoin-cli. Is bitcoind running?

Make sure you have bitcoind running and that bitcoin-cli is able to connect to bitcoind.

You can verify that your Bitcoin Core installation is ready for use by running:

    $ bitcoin-cli -regtest -rpcport=42599 -rpcuser=... -rpcpassword=... echo 'hello world'

bcli: 
Could not connect to bitcoind using bitcoin-cli. Is bitcoind running?

Make sure you have bitcoind running and that bitcoin-cli is able to connect to bitcoind.

You can verify that your Bitcoin Core installation is ready for use by running:

    $ bitcoin-cli -regtest -rpcport=60229 -rpcuser=... -rpcpassword=... echo 'hello world'

and after renaming ~/.bitcoin/bitcoin.conf the test passes:

simon@gamepc:~/git/SimonVrouwe/lightning$ DEVELOPER=1 PYTHONPATH=contrib/pylightning:contrib/pyln-client:contrib/pyln-testing:contrib/pyln-proto py.test -v -s tests/test_closing.py::test_closing
============================================================================================================================== test session starts ===============================================================================================================================
platform linux -- Python 3.7.3, pytest-5.3.1, py-1.8.0, pluggy-0.12.0 -- /usr/bin/python3
cachedir: .pytest_cache
benchmark: 3.2.2 (defaults: timer=time.perf_counter disable_gc=False min_rounds=5 min_time=0.000005 max_time=1.0 calibration_precision=10 warmup=False warmup_iterations=100000)
rootdir: /home/simon/git/SimonVrouwe/lightning
plugins: xdist-1.29.0, benchmark-3.2.2, flaky-3.6.1, timeout-1.3.3, test-groups-1.0.3, forked-1.0.2
collected 1 item                                                                                                                                                                                                                                                                 

tests/test_closing.py::test_closing Running tests in /tmp/ltests-xowjq0q5
PASSED

================================================================================================================================ warnings summary ================================================================================================================================
/home/simon/.local/lib/python3.7/site-packages/jinja2/utils.py:485
  /home/simon/.local/lib/python3.7/site-packages/jinja2/utils.py:485: DeprecationWarning: Using or importing the ABCs from 'collections' instead of from 'collections.abc' is deprecated, and in 3.8 it will stop working
    from collections import MutableMapping

/home/simon/.local/lib/python3.7/site-packages/jinja2/runtime.py:318
  /home/simon/.local/lib/python3.7/site-packages/jinja2/runtime.py:318: DeprecationWarning: Using or importing the ABCs from 'collections' instead of from 'collections.abc' is deprecated, and in 3.8 it will stop working
    from collections import Mapping

-- Docs: https://docs.pytest.org/en/latest/warnings.html
========================================================================================================================= 1 passed, 2 warnings in 50.97s =========================================================================================================================

[cdecker]

Excellent find @SimonVrouwe, I had not considered this before. I found that setting the $HOME environment variable will stop bitcoin-cli from accessing the user config, instead only relying on command line options and configs that we create as part of the tests.

I haven't tested it using strace like you did, but causing a parser error in bitcoin-cli via an invalid config syntax had the same effect 😉

[SimonVrouwe]

edit: please ignore below, I forgot to give CL the bitcoin-datadir option, sorry

@darosior ~It looks like bitcoin-cli is called without -datadir option in~: https://github.com/ElementsProject/lightning/blob/f637b88932d97ad640ba336b230052d2cd7749ba/plugins/bcli.c#L835-L839

~because bitcoind->datadir is still null.~

https://github.com/ElementsProject/lightning/blob/f637b88932d97ad640ba336b230052d2cd7749ba/plugins/bcli.c#L100-L101

~and then bitcoin-cli tries to find the (default) $HOME/.bitcoin/bitcoin.conf~

[SimonVrouwe]

@cdecker Ok I was half right about the -bitcoin-datadir option. That CL option is not set by default in (most of) the pytests, for example via a node_factory.get_node().

Adding the option manually, i.e.: l1 = node_factory.get_node(options={'bitcoin-datadir': bitcoind.bitcoin_dir}) prevents bitcoin-cli looking in $HOME/.bitcoin for bitcoin.conf (checked with strace)

Maybe as an extra precaution the bitcoin-datadir should be set by default in the pytests? But I guess setting $HOME to an empty folder has the same effect.

[cdecker]

Good point, I'll add the option in pyln-testing. Belts and suspenders :+1: