test: tool wallet test coverage for unexpected writes to wallet #15687

jonatack commented at 5:22 PM on March 28, 2019: member

This pull request adds test coverage in test/functional/tool_wallet.py to reproduce unexpected writes to the wallet as described in #15608 and serve as a benchmark for fixing the issue:

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.

Goals:

Reproduce the reported issue, define the current unexpected behavior, and add test coverage to guide a future fix. Add debug-level logging for sanity checking and commented-out assertions to be uncommented when fixing the issue. Add the same coverage to the wallet tool create test and the getwalletinfo test as regression tests while fixing the issue.
Add info log messages as there are currently none in the test file.
Split the tests out to separate functions as per review feedback.

Thanks to Marco Falke for pointing me in the right direction.

in test/functional/tool_wallet.py:43 in 6d9b033e3d outdated

  38 | @@ -36,8 +39,29 @@ def assert_tool_output(self, output, *args):
  39 |          assert_equal(stderr, '')
  40 |          assert_equal(stdout, output)
  41 |  
  42 | -    def run_test(self):
  43 | +    def wallet_path(self):
  44 | +        return os.path.join(self.nodes[0].datadir, "regtest", "wallets", "wallet.dat")

jonatack commented at 5:26 PM on March 28, 2019:

Use single quotes here like the rest of the file.

DrahtBot commented at 6:48 PM on March 28, 2019: member

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

No conflicts as of last run.

in test/functional/tool_wallet.py:61 in 6d9b033e3d outdated

  57 | +        self.log.info('Wallet file timestamp {0}: {1}'.format(op, timestamp))
  58 | +        return timestamp
  59 |  
  60 | +    def log_wallet_timestamp_comparison(self, new, old):
  61 | +        result = 'unchanged' if new == old else 'increased! **FIX ME**'
  62 | +        self.log.info('Wallet file timestamp {0}\n'.format(result))

MarcoFalke commented at 8:52 PM on March 28, 2019:

nit: instead of logging the timestamps and whether they changed, you might use assert_equal (or explicitly comment it out, if it currently fails)

jonatack commented at 2:59 PM on April 2, 2019:

Thanks for reviewing! I added both logs and assertions with the logs serving as a sanity check for the assertions. Based on your feedback, I switched the assertions from passing ones that need to be inverted, to failing ones that need to be uncommented.

in test/functional/tool_wallet.py:83 in 6d9b033e3d outdated

  79 | +        # This needs to be fixed.
  80 | +        self.log.info('Set wallet file permissions to read-only')
  81 | +        os.chmod(self.wallet_path(), 0o400)
  82 | +        self.log.info('Call wallet tool info')
  83 | +        self.assert_raises_tool_error('Error loading . Is wallet being used by another process?', 'info')
  84 | +        self.log.info('Wallet tool info command raises loading error! **FIX ME**')

MarcoFalke commented at 8:53 PM on March 28, 2019:

TODO's shouldn't be logged, but added as inline comments

jonatack commented at 3:00 PM on April 2, 2019:

Done. Waiting for Travis CI to pass locally and then will push a rebased update.

DrahtBot added the label Tests on Mar 28, 2019

jonatack force-pushed on Apr 3, 2019

jonatack referenced this in commit a0dc1ab5c7 on Apr 4, 2019

jonatack force-pushed on Apr 5, 2019

jonatack commented at 11:19 AM on April 5, 2019: member

Lowered the buffer size for the shasum function to 16Kb and hoisted that value to a constant. Rebased.

This should be ready for review.

in test/functional/tool_wallet.py:165 in 96e69a2ace outdated

 160 | @@ -87,15 +161,32 @@ def run_test(self):
 161 |              Address Book: 0
 162 |          ''')
 163 |          self.assert_tool_output(out, '-wallet=foo', 'create')
 164 | -
 165 | +        shasum_after = self.wallet_shasum()

laanwj commented at 1:44 PM on June 17, 2019:

I understand surrounding the info methods, but what is the logic here? creating a wallet that already exists should leave it untouched?

jonatack commented at 7:50 PM on July 2, 2019:

Yes, updated test name and logging to clarify that a bit. Happy to remove if you reckon it isn't a useful safeguard while fixing the issue.

laanwj commented at 1:45 PM on June 17, 2019: member

Looks good to me ACK 96e69a2ace8b0db496a0c429f05ccd5cb2f39c94

in test/functional/tool_wallet.py:46 in 96e69a2ace outdated

  41 | @@ -36,8 +42,32 @@ def assert_tool_output(self, output, *args):
  42 |          assert_equal(stderr, '')
  43 |          assert_equal(stdout, output)
  44 |  
  45 | -    def run_test(self):
  46 | +    def wallet_path(self):
  47 | +        return os.path.join(self.nodes[0].datadir, 'regtest', 'wallets', 'wallet.dat')

MarcoFalke commented at 5:55 PM on June 24, 2019:

style-nit: Could be a "const" member, set in the first line of run_test?

self.wallet_path = os.path.join(...

jonatack commented at 7:43 PM on July 2, 2019:

Done.

in test/functional/tool_wallet.py:58 in 96e69a2ace outdated

  54 | +                h.update(mv[:n])
  55 | +        return h.hexdigest()
  56 | +
  57 | +    def wallet_timestamp(self, op):
  58 | +        timestamp = os.path.getmtime(self.wallet_path())
  59 | +        self.log.info('Wallet file timestamp {0}: {1}'.format(op, timestamp))

MarcoFalke commented at 6:02 PM on June 24, 2019:

style-nit: Is it required to log the timestamp in a simple getter method? I'd prefer if it was logged by the caller or just asserted (Looks like you already do both of that)

jonatack commented at 7:43 PM on July 2, 2019:

Done.

in test/functional/tool_wallet.py:63 in 96e69a2ace outdated

  59 | +        self.log.info('Wallet file timestamp {0}: {1}'.format(op, timestamp))
  60 | +        return timestamp
  61 |  
  62 | +    def log_wallet_permissions(self):
  63 | +        result = oct(os.lstat(self.wallet_path()).st_mode)[-3:]
  64 | +        self.log.info('Verifying wallet file permissions: {}'.format(result))

MarcoFalke commented at 6:03 PM on June 24, 2019:

You aren't verifying anything here, it seems. I'd prefer if this was just a simple getter util method and the caller logs/asserts if appropriate.

jonatack commented at 7:45 PM on July 2, 2019:

Done.

in test/functional/tool_wallet.py:67 in 96e69a2ace outdated

  63 | +        result = oct(os.lstat(self.wallet_path()).st_mode)[-3:]
  64 | +        self.log.info('Verifying wallet file permissions: {}'.format(result))
  65 | +
  66 | +    def log_wallet_timestamp_comparison(self, old, new):
  67 | +        result = 'unchanged' if new == old else 'increased!'
  68 | +        self.log.info('Wallet file timestamp {}\n'.format(result))

MarcoFalke commented at 6:05 PM on June 24, 2019:

This looks like a test-dev debug statement. Maybe use self.log.debug?

jonatack commented at 7:46 PM on July 2, 2019:

Done, switched to loglevel debug for all the timestamp and shasum logging.

in test/functional/tool_wallet.py:125 in 96e69a2ace outdated

 125 | +
 126 | +        self.log.info('Stopping node\n')
 127 |          self.stop_node(0)
 128 |  
 129 | +        self.log.info('Calling wallet tool info after generating a transaction')
 130 | +        shasum_before = self.wallet_shasum()

MarcoFalke commented at 6:08 PM on June 24, 2019:

Looks like you are overwriting a previous symbol with the same name. I think it is clearer to split the tests into smaller ones, so that overwriting does not happen. I.e.

  self run_test(self):
   self.run_test_foo_bar()
   self.run_test_gen_tx()

  def run_test_foo_bar(self):
    assert True

...

jonatack commented at 7:46 PM on July 2, 2019:

Done.

MarcoFalke commented at 6:09 PM on June 24, 2019: member

some style-nits

jonatack force-pushed on Jul 2, 2019

jonatack commented at 8:19 PM on July 2, 2019: member

Linter is complaining about unused code because it is in the commented-out tests and Appveyor seems to keep file perms at 666. Reworking.

jonatack force-pushed on Jul 2, 2019

jonatack force-pushed on Jul 3, 2019

jonatack commented at 10:10 AM on July 8, 2019: member

Thanks for the review @laanwj and @MarcoFalke. I've pushed rebased commits that address your feedback. Are you able to rereview/retest?

test: Add log messages to test/functional/tool_wallet.py

and update code comments as per Python PEP 8 style guide.

1eb13f09a9

test: Split tool_wallet.py test into subtests

as per Marco Falke review suggestion.

3bf2b3a37b

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 https://github.com/bitcoin/bitcoin/issues/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.

7195fa792f

jonatack force-pushed on Jul 8, 2019

laanwj commented at 12:56 PM on July 8, 2019: member

code review ACK 7195fa792fcc19e9c064c4e38814c3b46a210b34

laanwj merged this on Jul 8, 2019

laanwj closed this on Jul 8, 2019

laanwj referenced this in commit b5fa2319d8 on Jul 8, 2019

jonatack deleted the branch on Jul 8, 2019

jonatack commented at 4:29 PM on July 8, 2019: member

The lone Travis failure appears to be an unrelated wait_until timeout > 60 sec in feature_block.py.

sidhujag referenced this in commit 3eef7b22aa on Jul 9, 2019

jasonbcox referenced this in commit 2030c4ba65 on Oct 1, 2020

vijaydasmp referenced this in commit 7b692e00b9 on Dec 6, 2021

vijaydasmp referenced this in commit 8a1097d724 on Dec 10, 2021

vijaydasmp referenced this in commit 0087a7924a on Dec 13, 2021

vijaydasmp referenced this in commit 1849b8e10d on Dec 13, 2021

vijaydasmp referenced this in commit 3d8be2d355 on Dec 15, 2021

MarcoFalke locked this on Dec 16, 2021