test: Tool wallet test coverage for unexpected writes to wallet

This commit adds test coverage in `test/functional/tool_wallet.py` to reproduce unexpected writes to the wallet as described in bitcoin/bitcoin#15608:

    - wallet tool `info` unexpectedly writes to the wallet file if the wallet file permissions are read/write.

    - wallet tool `info` raises with "Error loading . Is wallet being used by another process?" if the wallet file permissions are read-only.

1. Reproduce the reported issue, define the current unexpected behavior, and add test coverage to guide a future fix in the form of commented-out assertions to be uncommented when testing/fixing.

2. Provisionally extend the same coverage to the wallet tool create test and the getwalletinfo test as regression tests while fixing the issue.

3. Add some logging for sanity checking.

------

Changes after rebase:

5. Make wallet_path an instance method instead of a function in tool_wallet.py as per Marco Falke review suggestion.

6. Assert wallet permissions instead of logging them in tool_wallet.py. This ran into an issue with Appveyor keeping permissions at 666 so allowed for 666 as a workaround.

7. Change the added logging from info to debug level.

8. More helpful assertions order in tool_wallet.py#assert_tool_output. This change makes #assert_tool_output raise "Error loading wallet.dat. Is wallet being used by another process?" rather than a less-helpful message when debugging the read-only wallet permissions issue.

Author: jonatack

test/functional/tool_wallet.py

@@ -4,12 +4,17 @@
 # file COPYING or http://www.opensource.org/licenses/mit-license.php.
 """Test bitcoin-wallet."""
 
+import hashlib
+import os
+import stat
 import subprocess
 import textwrap
 
 from test_framework.test_framework import BitcoinTestFramework
 from test_framework.util import assert_equal
 
+BUFFER_SIZE = 16 * 1024
+
 class ToolWalletTest(BitcoinTestFramework):
     def set_test_params(self):
         self.num_nodes = 1
@@ -33,9 +38,27 @@ def assert_raises_tool_error(self, error, *args):
     def assert_tool_output(self, output, *args):
         p = self.bitcoin_wallet_process(*args)
         stdout, stderr = p.communicate()
-        assert_equal(p.poll(), 0)
         assert_equal(stderr, '')
         assert_equal(stdout, output)
+        assert_equal(p.poll(), 0)
+
+    def wallet_shasum(self):
+        h = hashlib.sha1()
+        mv = memoryview(bytearray(BUFFER_SIZE))
+        with open(self.wallet_path, 'rb', buffering=0) as f:
+            for n in iter(lambda : f.readinto(mv), 0):
+                h.update(mv[:n])
+        return h.hexdigest()
+
+    def wallet_timestamp(self):
+        return os.path.getmtime(self.wallet_path)
+
+    def wallet_permissions(self):
+        return oct(os.lstat(self.wallet_path).st_mode)[-3:]
+
+    def log_wallet_timestamp_comparison(self, old, new):
+        result = 'unchanged' if new == old else 'increased!'
+        self.log.debug('Wallet file timestamp {}'.format(result))
 
     def test_invalid_tool_commands_and_args(self):
         self.log.info('Testing that various invalid commands raise with specific error messages')
@@ -51,6 +74,18 @@ def test_tool_wallet_info(self):
         # Stop the node to close the wallet to call the info command.
         self.stop_node(0)
         self.log.info('Calling wallet tool info, testing output')
+        #
+        # TODO: Wallet tool info should work with wallet file permissions set to
+        # read-only without raising:
+        # "Error loading wallet.dat. Is wallet being used by another process?"
+        # The following lines should be uncommented and the tests still succeed:
+        #
+        # self.log.debug('Setting wallet file permissions to 400 (read-only)')
+        # os.chmod(self.wallet_path, stat.S_IRUSR)
+        # assert(self.wallet_permissions() in ['400', '666']) # Sanity check. 666 because Appveyor.
+        # shasum_before = self.wallet_shasum()
+        timestamp_before = self.wallet_timestamp()
+        self.log.debug('Wallet file timestamp before calling info: {}'.format(timestamp_before))
         out = textwrap.dedent('''\
             Wallet info
             ===========
@@ -61,6 +96,20 @@ def test_tool_wallet_info(self):
             Address Book: 3
         ''')
         self.assert_tool_output(out, '-wallet=wallet.dat', 'info')
+        timestamp_after = self.wallet_timestamp()
+        self.log.debug('Wallet file timestamp after calling info: {}'.format(timestamp_after))
+        self.log_wallet_timestamp_comparison(timestamp_before, timestamp_after)
+        self.log.debug('Setting wallet file permissions back to 600 (read/write)')
+        os.chmod(self.wallet_path, stat.S_IRUSR | stat.S_IWUSR)
+        assert(self.wallet_permissions() in ['600', '666']) # Sanity check. 666 because Appveyor.
+        #
+        # TODO: Wallet tool info should not write to the wallet file.
+        # The following lines should be uncommented and the tests still succeed:
+        #
+        # assert_equal(timestamp_before, timestamp_after)
+        # shasum_after = self.wallet_shasum()
+        # assert_equal(shasum_before, shasum_after)
+        # self.log.debug('Wallet file shasum unchanged\n')
 
     def test_tool_wallet_info_after_transaction(self):
         """
@@ -73,6 +122,9 @@ def test_tool_wallet_info_after_transaction(self):
         self.stop_node(0)
 
         self.log.info('Calling wallet tool info after generating a transaction, testing output')
+        shasum_before = self.wallet_shasum()
+        timestamp_before = self.wallet_timestamp()
+        self.log.debug('Wallet file timestamp before calling info: {}'.format(timestamp_before))
         out = textwrap.dedent('''\
             Wallet info
             ===========
@@ -83,9 +135,22 @@ def test_tool_wallet_info_after_transaction(self):
             Address Book: 3
         ''')
         self.assert_tool_output(out, '-wallet=wallet.dat', 'info')
+        shasum_after = self.wallet_shasum()
+        timestamp_after = self.wallet_timestamp()
+        self.log.debug('Wallet file timestamp after calling info: {}'.format(timestamp_after))
+        self.log_wallet_timestamp_comparison(timestamp_before, timestamp_after)
+        #
+        # TODO: Wallet tool info should not write to the wallet file.
+        # This assertion should be uncommented and succeed:
+        # assert_equal(timestamp_before, timestamp_after)
+        assert_equal(shasum_before, shasum_after)
+        self.log.debug('Wallet file shasum unchanged\n')
 
     def test_tool_wallet_create_on_existing_wallet(self):
         self.log.info('Calling wallet tool create on an existing wallet, testing output')
+        shasum_before = self.wallet_shasum()
+        timestamp_before = self.wallet_timestamp()
+        self.log.debug('Wallet file timestamp before calling create: {}'.format(timestamp_before))
         out = textwrap.dedent('''\
             Topping up keypool...
             Wallet info
@@ -97,21 +162,41 @@ def test_tool_wallet_create_on_existing_wallet(self):
             Address Book: 0
         ''')
         self.assert_tool_output(out, '-wallet=foo', 'create')
+        shasum_after = self.wallet_shasum()
+        timestamp_after = self.wallet_timestamp()
+        self.log.debug('Wallet file timestamp after calling create: {}'.format(timestamp_after))
+        self.log_wallet_timestamp_comparison(timestamp_before, timestamp_after)
+        assert_equal(timestamp_before, timestamp_after)
+        assert_equal(shasum_before, shasum_after)
+        self.log.debug('Wallet file shasum unchanged\n')
 
     def test_getwalletinfo_on_different_wallet(self):
         self.log.info('Starting node with arg -wallet=foo')
         self.start_node(0, ['-wallet=foo'])
 
         self.log.info('Calling getwalletinfo on a different wallet ("foo"), testing output')
+        shasum_before = self.wallet_shasum()
+        timestamp_before = self.wallet_timestamp()
+        self.log.debug('Wallet file timestamp before calling getwalletinfo: {}'.format(timestamp_before))
         out = self.nodes[0].getwalletinfo()
         self.stop_node(0)
 
+        shasum_after = self.wallet_shasum()
+        timestamp_after = self.wallet_timestamp()
+        self.log.debug('Wallet file timestamp after calling getwalletinfo: {}'.format(timestamp_after))
+
         assert_equal(0, out['txcount'])
         assert_equal(1000, out['keypoolsize'])
         assert_equal(1000, out['keypoolsize_hd_internal'])
         assert_equal(True, 'hdseedid' in out)
 
+        self.log_wallet_timestamp_comparison(timestamp_before, timestamp_after)
+        assert_equal(timestamp_before, timestamp_after)
+        assert_equal(shasum_after, shasum_before)
+        self.log.debug('Wallet file shasum unchanged\n')
+
     def run_test(self):
+        self.wallet_path = os.path.join(self.nodes[0].datadir, 'regtest', 'wallets', 'wallet.dat')
         self.test_invalid_tool_commands_and_args()
         # Warning: The following tests are order-dependent.
         self.test_tool_wallet_info()