wallet: Log when Wallet::SetMinVersion sets a different minversion #25896

ZenulAbidin commented at 9:08 PM on August 21, 2022: contributor

This change prints a single additional line in the debug.log when bitcoin-cli loads a wallet using loadwallet (not createwallet).

When Bitcoin Core creates a wallet, it's minversion is set to FEATURE_BASE, which is 10500. However, once the wallet is unloaded using unloadwallet or through program termination, and subsequently loaded again, loadwallet updates the minversion in the wallet.dat file to FEATURE_LATEST, currently 169900.

The current logging format prints the very old wallet version during createwallet, and then the actual version in calls to loadwallet. This has confused at least one person (reference - I was the one who asked there if there were plans to change that behavior, and was subsequently redirected here by achow), so it will be very helpful to users to explicitly specify in the logs what the walletdb is doing.

fanquake added the label Wallet on Aug 21, 2022

achow101 commented at 10:39 PM on August 21, 2022: member

This is incorrect. loadwallet does not change the wallet version. It occurs during CWallet::Create, which calls WalletBatch::LoadWallet in order to create the db file. The "incorrect" log line occurs during this LoadWallet. We will never change the wallet file version without explicit user action as it is a compatibility breaking change.

DrahtBot commented at 1:30 AM on August 22, 2022: contributor

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

Conflicts

No conflicts as of last run.

ZenulAbidin commented at 3:57 AM on August 22, 2022: contributor

This is incorrect. loadwallet does not change the wallet version. It occurs during CWallet::Create, which calls WalletBatch::LoadWallet in order to create the db file. The "incorrect" log line occurs during this LoadWallet.

Yeah, obviously I had to know that since the section that updates the wallet version is in WalletBatch::LoadWallet. The reason I said it came from loadwallet is because during my testing, calling the loadwallet RPC call eventually triggers WalletBatch::Loadwallet. I was never able to trigger this function from createwallet. Here is part of my debug.log output on regtest to supplement this hypothesis:

2022-08-21T20:52:10Z [rpc] ThreadRPCServer method=createwallet user=notatether                                                                                                                                                                                                
2022-08-21T20:52:10Z Using SQLite Version 3.31.1                                                                                                                                                                                                                              
2022-08-21T20:52:10Z Using wallet /home/zenulabidin/.bitcoin/regtest/wallets/prtest7                                                                                                                                                                                          
2022-08-21T20:52:10Z init message: Loading wallet…                                                                                                                                                                                                                            
2022-08-21T20:52:10Z [prtest7] Wallet file version = 10500, last client version = 239900                                                                                                                                                                                      
2022-08-21T20:52:10Z [prtest7] Keys: 0 plaintext, 0 encrypted, 0 w/ metadata, 0 total. Unknown wallet records: 0                                                                                                                                                              
2022-08-21T20:52:11Z [prtest7] Setting spkMan to active: id = 1e60986d600b86b498d7f5fec0984af074366a234cc825b16e66ef229632b066, type = legacy, internal = false                                                                                                               
2022-08-21T20:52:12Z [prtest7] Setting spkMan to active: id = 8189854c5db714cc58ffc1ab7ae4f1fa340e25d8252f1a9e7f1a20221b96d05c, type = p2sh-segwit, internal = false                                                                                                          
2022-08-21T20:52:12Z [prtest7] Setting spkMan to active: id = efe8901b28b0330fca53a354d32290377c3014f5712faaebd9b552b43cd05a1c, type = bech32, internal = false                                                                                                               
2022-08-21T20:52:13Z [prtest7] Setting spkMan to active: id = 93591c1fd54c434bed79a12d75a36d9cdd9d14f2a503e95d3cbd42699205b83d, type = bech32m, internal = false                                                                                                              
2022-08-21T20:52:14Z [prtest7] Setting spkMan to active: id = 32a04d1773be2f4bf3b9a3fd39b1ac66145d2b7d0dc15424ae1e71cd3ea52203, type = legacy, internal = true                                                                                                                
2022-08-21T20:52:15Z [prtest7] Setting spkMan to active: id = 0093bc4675eb72f188f0729bf2bccdcdf09039d6c51686b9a00edfa51247d293, type = p2sh-segwit, internal = true                                                                                                           
2022-08-21T20:52:16Z [prtest7] Setting spkMan to active: id = b67e3643f790b7e0ba855067b8fa97ba386022aed984cd2b347b7570fcbbd335, type = bech32, internal = true                                                                                                                
2022-08-21T20:52:17Z [prtest7] Setting spkMan to active: id = fa147979b83634d90d47adb6af966a54d7a5f908a081b7dce42da9f8e49c2338, type = bech32m, internal = true                                                                                                               
2022-08-21T20:52:17Z [prtest7] Wallet completed loading in            7325ms                                                                                                                                                                                                  
2022-08-21T20:52:18Z [prtest7] setKeyPool.size() = 8000                                                                                                                                                                                                                       
2022-08-21T20:52:18Z [prtest7] mapWallet.size() = 0                                                                                                                                                                                                                           
2022-08-21T20:52:18Z [prtest7] m_address_book.size() = 0                                                                                                                                                                                                                      
...
2022-08-21T20:52:53Z [rpc] ThreadRPCServer method=unloadwallet user=notatether                                                                                                                                                                                                
2022-08-21T20:52:53Z [prtest7] Releasing wallet                                                                                                                                                                                                                               
2022-08-21T20:53:02Z [rpc] ThreadRPCServer method=loadwallet user=notatether                                                                                                                                                                                                  
2022-08-21T20:53:02Z Using SQLite Version 3.31.1                                                                                                                                                                                                                              
2022-08-21T20:53:02Z Using wallet /home/zenulabidin/.bitcoin/regtest/wallets/prtest7                                                                                                                                                                                          
2022-08-21T20:53:02Z init message: Loading wallet…                                                                                                                                                                                                                            
2022-08-21T20:53:02Z [prtest7] Changing minversion from 10500 to 169900                                                                                                                                                                                                       
2022-08-21T20:53:02Z [prtest7] Setting spkMan to active: id = 1e60986d600b86b498d7f5fec0984af074366a234cc825b16e66ef229632b066, type = legacy, internal = false                                                                                                               
2022-08-21T20:53:02Z [prtest7] Setting spkMan to active: id = 8189854c5db714cc58ffc1ab7ae4f1fa340e25d8252f1a9e7f1a20221b96d05c, type = p2sh-segwit, internal = false                                                                                                          
2022-08-21T20:53:02Z [prtest7] Setting spkMan to active: id = efe8901b28b0330fca53a354d32290377c3014f5712faaebd9b552b43cd05a1c, type = bech32, internal = false                                                                                                               
2022-08-21T20:53:02Z [prtest7] Setting spkMan to active: id = 93591c1fd54c434bed79a12d75a36d9cdd9d14f2a503e95d3cbd42699205b83d, type = bech32m, internal = false                                                                                                              
2022-08-21T20:53:02Z [prtest7] Setting spkMan to active: id = 32a04d1773be2f4bf3b9a3fd39b1ac66145d2b7d0dc15424ae1e71cd3ea52203, type = legacy, internal = true                                                                                                                
2022-08-21T20:53:02Z [prtest7] Setting spkMan to active: id = 0093bc4675eb72f188f0729bf2bccdcdf09039d6c51686b9a00edfa51247d293, type = p2sh-segwit, internal = true                                                                                                           
2022-08-21T20:53:02Z [prtest7] Setting spkMan to active: id = b67e3643f790b7e0ba855067b8fa97ba386022aed984cd2b347b7570fcbbd335, type = bech32, internal = true                                                                                                                
2022-08-21T20:53:02Z [prtest7] Setting spkMan to active: id = fa147979b83634d90d47adb6af966a54d7a5f908a081b7dce42da9f8e49c2338, type = bech32m, internal = true                                                                                                               
2022-08-21T20:53:03Z [prtest7] Wallet file version = 169900, last client version = 239900                                                                                                                                                                                     
2022-08-21T20:53:03Z [prtest7] Keys: 8 plaintext, 0 encrypted, 0 w/ metadata, 8 total. Unknown wallet records: 0                                                                                                                                                              
2022-08-21T20:53:04Z [prtest7] Wallet completed loading in            1068ms                                                                                                                                                                                                  
2022-08-21T20:53:04Z [prtest7] setKeyPool.size() = 8000                                                                                                                                                                                                                       
2022-08-21T20:53:04Z [prtest7] mapWallet.size() = 0                                                                                                                                                                                                                           
2022-08-21T20:53:04Z [prtest7] m_address_book.size() = 0
... # Some time later, I repeated the unloadwallet/loadwallet sequence
2022-08-22T03:48:54Z [rpc] ThreadRPCServer method=unloadwallet user=notatether
2022-08-22T03:48:54Z [prtest7] Releasing wallet
2022-08-22T03:48:56Z [rpc] ThreadRPCServer method=loadwallet user=notatether
2022-08-22T03:48:56Z Using SQLite Version 3.31.1
2022-08-22T03:48:56Z Using wallet /home/zenulabidin/.bitcoin/regtest/wallets/prtest7
2022-08-22T03:48:56Z init message: Loading wallet…
2022-08-22T03:48:56Z [prtest7] Changing minversion from 10500 to 169900
2022-08-22T03:48:56Z [prtest7] Setting spkMan to active: id = 1e60986d600b86b498d7f5fec0984af074366a234cc825b16e66ef229632b066, type = legacy, internal = false
2022-08-22T03:48:56Z [prtest7] Setting spkMan to active: id = 8189854c5db714cc58ffc1ab7ae4f1fa340e25d8252f1a9e7f1a20221b96d05c, type = p2sh-segwit, internal = false
2022-08-22T03:48:56Z [prtest7] Setting spkMan to active: id = efe8901b28b0330fca53a354d32290377c3014f5712faaebd9b552b43cd05a1c, type = bech32, internal = false
2022-08-22T03:48:56Z [prtest7] Setting spkMan to active: id = 93591c1fd54c434bed79a12d75a36d9cdd9d14f2a503e95d3cbd42699205b83d, type = bech32m, internal = false
2022-08-22T03:48:56Z [prtest7] Setting spkMan to active: id = 32a04d1773be2f4bf3b9a3fd39b1ac66145d2b7d0dc15424ae1e71cd3ea52203, type = legacy, internal = true
2022-08-22T03:48:56Z [prtest7] Setting spkMan to active: id = 0093bc4675eb72f188f0729bf2bccdcdf09039d6c51686b9a00edfa51247d293, type = p2sh-segwit, internal = true
2022-08-22T03:48:56Z [prtest7] Setting spkMan to active: id = b67e3643f790b7e0ba855067b8fa97ba386022aed984cd2b347b7570fcbbd335, type = bech32, internal = true
2022-08-22T03:48:56Z [prtest7] Setting spkMan to active: id = fa147979b83634d90d47adb6af966a54d7a5f908a081b7dce42da9f8e49c2338, type = bech32m, internal = true
2022-08-22T03:48:57Z [prtest7] Wallet file version = 169900, last client version = 239900
2022-08-22T03:48:57Z [prtest7] Keys: 8 plaintext, 0 encrypted, 0 w/ metadata, 8 total. Unknown wallet records: 0
2022-08-22T03:48:57Z [prtest7] Wallet completed loading in             997ms
2022-08-22T03:48:58Z [prtest7] setKeyPool.size() = 8000
2022-08-22T03:48:58Z [prtest7] mapWallet.size() = 0
2022-08-22T03:48:58Z [prtest7] m_address_book.size() = 0

Notice how the new message is only printed during an RPC invocation of loadwallet.

achow101 commented at 4:53 AM on August 22, 2022: member

You misunderstand me.

It is incorrect to have the logline occur during loadwallet. It needs to occur with createwallet because the version is written during creating, not during loading. It is written somewhere in CWallet::Create, after that function has called LoadWallet.

Furthermore, what you have done is log the default value just before the actual minversion is read from the wallet file. This is completely useless information.

ZenulAbidin force-pushed on Aug 22, 2022

ZenulAbidin commented at 5:20 AM on August 22, 2022: contributor

It is incorrect to have the logline occur during loadwallet. It needs to occur with createwallet because the version is written during creating, not during loading. It is written somewhere in CWallet::Create, after that function has called LoadWallet.

Furthermore, what you have done is log the default value just before the actual minversion is read from the wallet file. This is completely useless information.

Changes have been implemented. Now the logging only prints the read minversion.

achow101 commented at 6:54 PM on August 23, 2022: member

Perhaps it would be better to have the log line in SetMinVersion itself so that it can log everywhere we actually upgrade the minimum version. Of course it should only log if the version is changed.

Please also change the PR title to reflect what the code does.

ZenulAbidin force-pushed on Aug 24, 2022

ZenulAbidin renamed this:
~~wallet: Log when loadwallet updates wallet minversion~~
wallet: Log when Wallet::SetMinVersion sets a different minversion
on Aug 24, 2022

ZenulAbidin commented at 10:26 AM on August 24, 2022: contributor

Perhaps it would be better to have the log line in SetMinVersion itself so that it can log everywhere we actually upgrade the minimum version. Of course it should only log if the version is changed.

Both of these adjustments have been made.

in src/wallet/wallet.cpp:545 in d3304806d7 outdated

 541 | @@ -542,6 +542,7 @@ void CWallet::SetMinVersion(enum WalletFeature nVersion, WalletBatch* batch_in)
 542 |      LOCK(cs_wallet);
 543 |      if (nWalletVersion >= nVersion)
 544 |          return;
 545 | +    this->WalletLogPrintf("Setting minversion to %d\n", nVersion);

achow101 commented at 10:07 PM on August 24, 2022:

this-> is unneeded.

ZenulAbidin commented at 5:54 PM on August 25, 2022:

@achow101 I pushed a revision without it (I actually had the patch ready since this afternoon, but I forgot to push it until now).

achow101 commented at 10:08 PM on August 24, 2022: member

Please also update the OP text to reflect the code.

ZenulAbidin force-pushed on Aug 25, 2022

Wallet::SetMinVersion - Log the new minversion 835bd27e9a

ZenulAbidin force-pushed on Aug 25, 2022

ZenulAbidin commented at 6:28 PM on August 26, 2022: contributor

Just a question, since I haven't done this kind of thing before:

Must I keep rebasing the FETCH_HEAD and force-pushing before this PR can be merged?

I'm asking because apparently other merges are being made and CONTRIBUTING.md says that maintainers might request to rebase the FETCH_HEAD first.

achow101 commented at 6:52 PM on August 26, 2022: member

@ZenulAbidin No, you do not need to keep rebasing. You only need to rebase if there are conflicts with master. Otherwise you shouldn't rebase as doing so invalidates acks. Other PRs are merged because they are ready - contributors have reviewed those. Of course reviewers can review anything they wish and so it is probable that there are other things that are higher priority that are getting review.

achow101 commented at 8:41 PM on August 26, 2022: member

ACK 835bd27e9a0dd627f266e3dc0a7422d8d0612eff

achow101 merged this on Aug 26, 2022

achow101 closed this on Aug 26, 2022

sidhujag referenced this in commit 1178d929c8 on Aug 26, 2022

ZenulAbidin deleted the branch on Aug 27, 2022

bitcoin locked this on Aug 27, 2023