Merge #12755: [tests] Better stderr testing

beee49b [tests] Allow stderr to be tested against specified string (John Newbery)
e503671 [Tests] Use LIBC_FATAL_STDERR_=1 in tests (John Newbery)
c22ce8a [Tests] Write stdout/stderr to datadir instead of temp file. (John Newbery)

Pull request description:

  **Due to a merge conflict, this is now based on #10267. Please review that PR first!**

  Subset of #12379 now that parts of that PR have been merged.

  #12362 was only observed when running the functional tests locally because:

  - by defatul libc logs to `/dev/tty` instead of stderr
  - the functional tests only check for substring inclusion in stderr when we're expecting bitcoind to fail.

  This PR tightens our checking of stderr and will cause tests to fail if there is any unexpected message in stderr:

  - commit *Write stdout/stderr to datadir instead of temp file* writes stderr to a file in the datadir instead of a temporary file. This helps with debugging in the case of failure.
  - commit *Use LIBC_FATAL_STDERR=1 in tests* ensures that libc failures are logged to stderr instead of the terminal.
  commit *Assert that bitcoind stdout is empty on shutdown* asserts that stderr is empty on bitcoind shutdown.

Tree-SHA512: 21111030e667b3b686f2a7625c2b625ebcfb6998e1cccb4f3932e8b5d21fb514b19a73ac971595d049343430e9a63155986a7f5648cad55b8f36f3c58b1c7048

Author: laanwj

test/functional/feature_includeconf.py

@@ -15,9 +15,8 @@
    file.
 """
 import os
-import tempfile
 
-from test_framework.test_framework import BitcoinTestFramework, assert_equal
+from test_framework.test_framework import BitcoinTestFramework
 
 class IncludeConfTest(BitcoinTestFramework):
     def set_test_params(self):
@@ -44,20 +43,18 @@ def run_test(self):
 
         self.log.info("-includeconf cannot be used as command-line arg. subversion should still end with 'main; relative)/'")
         self.stop_node(0)
-        with tempfile.SpooledTemporaryFile(max_size=2**16) as log_stderr:
-            self.start_node(0, extra_args=["-includeconf=relative2.conf"], stderr=log_stderr)
 
-            subversion = self.nodes[0].getnetworkinfo()["subversion"]
-            assert subversion.endswith("main; relative)/")
-            log_stderr.seek(0)
-            stderr = log_stderr.read().decode('utf-8').strip()
-            assert_equal(stderr, 'warning: -includeconf cannot be used from commandline; ignoring -includeconf=relative2.conf')
+        self.start_node(0, extra_args=["-includeconf=relative2.conf"])
+
+        subversion = self.nodes[0].getnetworkinfo()["subversion"]
+        assert subversion.endswith("main; relative)/")
+        self.stop_node(0, expected_stderr="warning: -includeconf cannot be used from commandline; ignoring -includeconf=relative2.conf")
 
         self.log.info("-includeconf cannot be used recursively. subversion should end with 'main; relative)/'")
         with open(os.path.join(self.options.tmpdir, "node0", "relative.conf"), "a", encoding="utf8") as f:
             f.write("includeconf=relative2.conf\n")
 
-        self.restart_node(0)
+        self.start_node(0)
 
         subversion = self.nodes[0].getnetworkinfo()["subversion"]
         assert subversion.endswith("main; relative)/")

test/functional/test_framework/test_framework.py

@@ -256,7 +256,7 @@ def add_nodes(self, num_nodes, extra_args=None, rpchost=None, timewait=None, bin
         assert_equal(len(extra_args), num_nodes)
         assert_equal(len(binary), num_nodes)
         for i in range(num_nodes):
-            self.nodes.append(TestNode(i, get_datadir_path(self.options.tmpdir, i), rpchost=rpchost, timewait=timewait, bitcoind=binary[i], bitcoin_cli=self.options.bitcoincli, stderr=None, mocktime=self.mocktime, coverage_dir=self.options.coveragedir, extra_conf=extra_confs[i], extra_args=extra_args[i], use_cli=self.options.usecli))
+            self.nodes.append(TestNode(i, get_datadir_path(self.options.tmpdir, i), rpchost=rpchost, timewait=timewait, bitcoind=binary[i], bitcoin_cli=self.options.bitcoincli, mocktime=self.mocktime, coverage_dir=self.options.coveragedir, extra_conf=extra_confs[i], extra_args=extra_args[i], use_cli=self.options.usecli))
 
     def start_node(self, i, *args, **kwargs):
         """Start a bitcoind"""
@@ -289,9 +289,9 @@ def start_nodes(self, extra_args=None, *args, **kwargs):
             for node in self.nodes:
                 coverage.write_all_rpc_commands(self.options.coveragedir, node.rpc)
 
-    def stop_node(self, i):
+    def stop_node(self, i, expected_stderr=''):
         """Stop a bitcoind test node"""
-        self.nodes[i].stop_node()
+        self.nodes[i].stop_node(expected_stderr)
         self.nodes[i].wait_until_stopped()
 
     def stop_nodes(self):
@@ -407,7 +407,7 @@ def _initialize_chain(self):
                 args = [self.options.bitcoind, "-datadir=" + datadir]
                 if i > 0:
                     args.append("-connect=127.0.0.1:" + str(p2p_port(0)))
-                self.nodes.append(TestNode(i, get_datadir_path(self.options.cachedir, i), extra_conf=["bind=127.0.0.1"], extra_args=[], rpchost=None, timewait=None, bitcoind=self.options.bitcoind, bitcoin_cli=self.options.bitcoincli, stderr=None, mocktime=self.mocktime, coverage_dir=None))
+                self.nodes.append(TestNode(i, get_datadir_path(self.options.cachedir, i), extra_conf=["bind=127.0.0.1"], extra_args=[], rpchost=None, timewait=None, bitcoind=self.options.bitcoind, bitcoin_cli=self.options.bitcoincli, mocktime=self.mocktime, coverage_dir=None))
                 self.nodes[i].args = args
                 self.start_node(i)
 

test/functional/test_framework/test_node.py

@@ -10,6 +10,7 @@
 import http.client
 import json
 import logging
+import os
 import re
 import subprocess
 import tempfile
@@ -55,17 +56,18 @@ class TestNode():
     To make things easier for the test writer, any unrecognised messages will
     be dispatched to the RPC connection."""
 
-    def __init__(self, i, datadir, rpchost, timewait, bitcoind, bitcoin_cli, stderr, mocktime, coverage_dir, extra_conf=None, extra_args=None, use_cli=False):
+    def __init__(self, i, datadir, rpchost, timewait, bitcoind, bitcoin_cli, mocktime, coverage_dir, extra_conf=None, extra_args=None, use_cli=False):
         self.index = i
         self.datadir = datadir
+        self.stdout_dir = os.path.join(self.datadir, "stdout")
+        self.stderr_dir = os.path.join(self.datadir, "stderr")
         self.rpchost = rpchost
         if timewait:
             self.rpc_timeout = timewait
         else:
             # Wait for up to 60 seconds for the RPC server to respond
             self.rpc_timeout = 60
         self.binary = bitcoind
-        self.stderr = stderr
         self.coverage_dir = coverage_dir
         if extra_conf != None:
             append_config(datadir, extra_conf)
@@ -124,17 +126,29 @@ def __getattr__(self, name):
             assert self.rpc_connected and self.rpc is not None, self._node_msg("Error: no RPC connection")
             return getattr(self.rpc, name)
 
-    def start(self, extra_args=None, stderr=None, *args, **kwargs):
+    def start(self, extra_args=None, stdout=None, stderr=None, *args, **kwargs):
         """Start the node."""
         if extra_args is None:
             extra_args = self.extra_args
+
+        # Add a new stdout and stderr file each time bitcoind is started
         if stderr is None:
-            stderr = self.stderr
+            stderr = tempfile.NamedTemporaryFile(dir=self.stderr_dir, delete=False)
+        if stdout is None:
+            stdout = tempfile.NamedTemporaryFile(dir=self.stdout_dir, delete=False)
+        self.stderr = stderr
+        self.stdout = stdout
+
         # Delete any existing cookie file -- if such a file exists (eg due to
         # unclean shutdown), it will get overwritten anyway by bitcoind, and
         # potentially interfere with our attempt to authenticate
         delete_cookie_file(self.datadir)
-        self.process = subprocess.Popen(self.args + extra_args, stderr=stderr, *args, **kwargs)
+
+        # add environment variable LIBC_FATAL_STDERR_=1 so that libc errors are written to stderr and not the terminal
+        subp_env = dict(os.environ, LIBC_FATAL_STDERR_="1")
+
+        self.process = subprocess.Popen(self.args + extra_args, env=subp_env, stdout=stdout, stderr=stderr, *args, **kwargs)
+
         self.running = True
         self.log.debug("bitcoind started, waiting for RPC to come up")
 
@@ -174,7 +188,7 @@ def get_wallet_rpc(self, wallet_name):
             wallet_path = "wallet/%s" % wallet_name
             return self.rpc / wallet_path
 
-    def stop_node(self):
+    def stop_node(self, expected_stderr=''):
         """Stop the node."""
         if not self.running:
             return
@@ -183,6 +197,13 @@ def stop_node(self):
             self.stop()
         except http.client.CannotSendRequest:
             self.log.exception("Unable to stop node.")
+
+        # Check that stderr is as expected
+        self.stderr.seek(0)
+        stderr = self.stderr.read().decode('utf-8').strip()
+        if stderr != expected_stderr:
+            raise AssertionError("Unexpected stderr {} != {}".format(stderr, expected_stderr))
+
         del self.p2ps[:]
 
     def is_node_stopped(self):
@@ -217,9 +238,10 @@ def assert_start_raises_init_error(self, extra_args=None, expected_msg=None, mat
 
         Will throw if bitcoind starts without an error.
         Will throw if an expected_msg is provided and it does not match bitcoind's stdout."""
-        with tempfile.SpooledTemporaryFile(max_size=2**16) as log_stderr:
+        with tempfile.NamedTemporaryFile(dir=self.stderr_dir, delete=False) as log_stderr, \
+             tempfile.NamedTemporaryFile(dir=self.stdout_dir, delete=False) as log_stdout:
             try:
-                self.start(extra_args, stderr=log_stderr, *args, **kwargs)
+                self.start(extra_args, stdout=log_stdout, stderr=log_stderr, *args, **kwargs)
                 self.wait_for_rpc_connection()
                 self.stop_node()
                 self.wait_until_stopped()

test/functional/test_framework/util.py

@@ -301,6 +301,8 @@ def initialize_datadir(dirname, n):
         f.write("keypool=1\n")
         f.write("discover=0\n")
         f.write("listenonion=0\n")
+        os.makedirs(os.path.join(datadir, 'stderr'), exist_ok=True)
+        os.makedirs(os.path.join(datadir, 'stdout'), exist_ok=True)
     return datadir
 
 def get_datadir_path(dirname, n):