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

4 files changed, 43 insertions, 22 deletions

diff --git a/test/functional/feature_includeconf.py b/test/functional/feature_includeconf.py
index d3f1be6c3a..1ead2fcb02 100755
--- a/test/functional/feature_includeconf.py
+++ b/test/functional/feature_includeconf.py
@@ -15,9 +15,8 @@ Verify that:
    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 @@ class IncludeConfTest(BitcoinTestFramework):
 
         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)/")
diff --git a/test/functional/test_framework/test_framework.py b/test/functional/test_framework/test_framework.py
index 3203cfa23f..b842e6ef4e 100755
--- a/test/functional/test_framework/test_framework.py
+++ b/test/functional/test_framework/test_framework.py
@@ -256,7 +256,7 @@ class BitcoinTestFramework(metaclass=BitcoinTestMetaClass):
         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 @@ class BitcoinTestFramework(metaclass=BitcoinTestMetaClass):
             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 @@ class BitcoinTestFramework(metaclass=BitcoinTestMetaClass):
                 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)
 
diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py
index 5a6a659392..eac6057de6 100755
--- a/test/functional/test_framework/test_node.py
+++ b/test/functional/test_framework/test_node.py
@@ -10,6 +10,7 @@ from enum import Enum
 import http.client
 import json
 import logging
+import os
 import re
 import subprocess
 import tempfile
@@ -55,9 +56,11 @@ 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
@@ -65,7 +68,6 @@ class TestNode():
             # 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 @@ class TestNode():
             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 @@ class TestNode():
             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 @@ class TestNode():
             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 @@ class TestNode():
 
         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()
diff --git a/test/functional/test_framework/util.py b/test/functional/test_framework/util.py
index 1daaa6c482..540727dc85 100644
--- a/test/functional/test_framework/util.py
+++ b/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):