test: Write tests for upgradewallet RPC #18767

Now that #15761 has been merged, it would be nice to have tests for it. They can be written by copying the file ./test/functional/feature_backwards_compatibility.py and modifying it to create a wallet with an older version, then check that it can be upgraded with a new version.

Useful skills:

Experience with the Bitcoin Core wallet and functional test suite.

Want to work on this issue?

The purpose of the good first issue label is to highlight which issues are suitable for a new contributor without a deep understanding of the codebase.

You do not need to request permission to start working on this. You are encouraged to comment on the issue if you are planning to work on it. This will help other contributors monitor which issues are actively being addressed and is also an effective way to request assistance if and when you need it.

For guidance on contributing, please read CONTRIBUTING.md before opening your pull request.

Will look into it.

Hi @MarcoFalke

Well, after having played ping pong with the test framework for a while, I came to this solution, that, in my opinion, is nothing but an ugly hack.

As I couldn't use older binaries to run test nodes (the docs are clear about that) I saw no other option than to manually setup and run a v0.16.3 node, that I needed to create an older wallet.

Not sure, if I should open a PR at all. Maybe only as draft for now?

Regards,

What are the issues you are seeing when running a 0.16 node with the test framework. Maybe they can be solved?

What are the issues you are seeing when running a 0.16 node with the test framework. Maybe they can be solved?

It simply doesn't start the node. Although I've downloaded the v0.16.3 binaries and configured them similarly to those from ./test/functional/feature_backwards_compatibility.py the framework can't start them. The error gets thrown in test_node.py's wait_for_rpcconnection. Usually, it should be able to call rpc.blockcount from there, but as it can't create a proper RPC connection there is no way to continue test.

So I did it manually.

What is the log (combined_log.py) ?

What is the log (combined_log.py) ?

I have included the previous entries to my current test.

self.add_nodes(self.num_nodes, extra_args=self.extra_args, versions=[
            None,
            160300,
        ], binary=[
            self.options.bitcoind,
            releases_path + "/v0.16.3/bin/bitcoind",
        ], binary_cli=[
            self.options.bitcoincli,
            releases_path + "/v0.16.3/bin/bitcoin-cli",
        ])

Then I have started the test (so it tries to run v0.16.3 the same way it does with newer version).

This is the combined_logs.py output.

./test/functional/combine_logs.py                                               (1) (1m 2s 828ms) ┃
Opening latest test directory: /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7
 node1                                    2020-04-26 11:56:40.815959  
                                   2020-04-26 11:56:40.819755 Bitcoin Core version v0.16.3 (release build)
                                   2020-04-26 11:56:40.819802 InitParameterInteraction: parameter interaction: -whitelistforcerelay=1 -> setting -whitelistrelay=1
                                   2020-04-26 11:56:40.819845 Validating signatures for all blocks.
                                   2020-04-26 11:56:40.819864 Setting nMinimumChainWork=0000000000000000000000000000000000000000000000000000000000000000
                                   2020-04-26 11:56:40.821144 Using the 'sse4' SHA256 implementation
                                   2020-04-26 11:56:40.821166 Using RdRand as an additional entropy source
                                   2020-04-26 11:56:40.843335 Default data directory /Users/brakmic/Library/Application Support/Bitcoin
                                   2020-04-26 11:56:40.843386 Using data directory /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node1/regtest
                                   2020-04-26 11:56:40.843422 Using config file /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node1/bitcoin.conf
                                   2020-04-26 11:56:40.843460 Using at most 125 automatic connections (8192 file descriptors available)
                                   2020-04-26 11:56:40.852177 Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
                                   2020-04-26 11:56:40.862566 Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
                                   2020-04-26 11:56:40.862634 Using 2 threads for script verification
                                   2020-04-26 11:56:40.862728 scheduler thread start
                                   2020-04-26 11:56:40.864468 Allowing HTTP connections from: 127.0.0.0/8 ::1/128 
                                   2020-04-26 11:56:40.866260 Binding RPC on address ::1 port 18443
                                   2020-04-26 11:56:40.872933 Binding RPC on address 127.0.0.1 port 18443
                                   2020-04-26 11:56:40.873025 Initialized HTTP server
                                   2020-04-26 11:56:40.873054 HTTP: creating work queue of depth 16
                                   2020-04-26 11:56:40.873075 Starting RPC
                                   2020-04-26 11:56:40.873113 Starting HTTP RPC server
                                   2020-04-26 11:56:40.873134 No rpcpassword set - using random cookie authentication
                                   2020-04-26 11:56:40.873470 Generated RPC authentication cookie /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node1/regtest/.cookie
                                   2020-04-26 11:56:40.873508 Registering HTTP handler for / (exactmatch 1)
                                   2020-04-26 11:56:40.873532 Registering HTTP handler for /wallet/ (exactmatch 0)
                                   2020-04-26 11:56:40.873558 Starting HTTP server
                                   2020-04-26 11:56:40.873578 HTTP: starting 4 worker threads
                                   2020-04-26 11:56:40.873642 Entering http event loop
                                   2020-04-26 11:56:40.873704 Using wallet directory /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node1/regtest/wallets
                                   2020-04-26 11:56:40.873771 init message: Verifying wallet(s)...
                                   2020-04-26 11:56:40.873912 Using BerkeleyDB version Berkeley DB 4.8.30: (April  9, 2010)
                                   2020-04-26 11:56:40.873942 Using wallet wallet.dat
                                   2020-04-26 11:56:40.874210 CDBEnv::Open: LogDir=/var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node1/regtest/wallets/database ErrorFile=/var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node1/regtest/wallets/db.log
                                   2020-04-26 11:56:40.895366 net: setting try another outbound peer=false
                                   2020-04-26 11:56:40.896207 Cache configuration:
                                   2020-04-26 11:56:40.896253 * Using 2.0MiB for block index database
                                   2020-04-26 11:56:40.896277 * Using 8.0MiB for chain state database
                                   2020-04-26 11:56:40.896298 * Using 440.0MiB for in-memory UTXO set (plus up to 286.1MiB of unused mempool space)
                                   2020-04-26 11:56:40.896320 init message: Loading block index...
                                   2020-04-26 11:56:40.897008 Opening LevelDB in /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node1/regtest/blocks/index
                                   2020-04-26 11:56:40.944595 Opened LevelDB successfully
                                   2020-04-26 11:56:40.944751 Using obfuscation key for /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node1/regtest/blocks/index: 0000000000000000
                                   2020-04-26 11:56:40.945289 LoadBlockIndexDB: last block file = 0
                                   2020-04-26 11:56:40.945415 LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=0, size=0, heights=0...0, time=1970-01-01...1970-01-01)
                                   2020-04-26 11:56:40.945462 Checking all blk files are present...
                                   2020-04-26 11:56:40.945520 LoadBlockIndexDB: transaction index disabled
                                   2020-04-26 11:56:40.945639 Initializing databases...
                                   2020-04-26 11:56:40.946150 Pre-allocating up to position 0x1000000 in blk00000.dat
                                   2020-04-26 11:56:40.976107 Opening LevelDB in /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node1/regtest/chainstate
                                   2020-04-26 11:56:41.016356 Opened LevelDB successfully
                                   2020-04-26 11:56:41.016502 Wrote new obfuscate key for /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node1/regtest/chainstate: 213f82d42b179542
                                   2020-04-26 11:56:41.016540 Using obfuscation key for /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node1/regtest/chainstate: 213f82d42b179542
                                   2020-04-26 11:56:41.016606 init message: Rewinding blocks...
                                   2020-04-26 11:56:41.016642  block index             120ms
                                   2020-04-26 11:56:41.016708 init message: Loading wallet...
                                   2020-04-26 11:56:41.143143 nFileVersion = 160300
                                   2020-04-26 11:56:41.144104 Keys: 0 plaintext, 0 encrypted, 0 w/ metadata, 0 total
                                   2020-04-26 11:56:41.230872 Performing wallet upgrade to 60000
                                   2020-04-26 11:56:43.095054 keypool added 2000 keys (1000 internal), size=2000 (1000 internal)
                                   2020-04-26 11:56:43.186474  wallet                 2170ms
                                   2020-04-26 11:56:43.186784 setKeyPool.size() = 2000
                                   2020-04-26 11:56:43.186842 mapWallet.size() = 0
                                   2020-04-26 11:56:43.186881 mapAddressBook.size() = 0
                                   2020-04-26 11:56:43.187518   - Load block from disk: 0.23ms [0.00s]
                                   2020-04-26 11:56:43.188005   - Connect total: 0.48ms [0.00s (infms/blk)]
                                   2020-04-26 11:56:43.188089   - Flush: 0.10ms [0.00s (infms/blk)]
                                   2020-04-26 11:56:43.188154   - Writing chainstate: 0.07ms [0.00s (infms/blk)]
                                   2020-04-26 11:56:43.188256 UpdateTip: new best=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 height=0 version=0x00000001 log2_work=1 tx=1 date='2011-02-02 23:16:42' progress=1.000000 cache=0.0MiB(0txo)
                                   2020-04-26 11:56:43.188320   - Connect postprocess: 0.17ms [0.00s (infms/blk)]
                                   2020-04-26 11:56:43.188360 - Connect block: 1.04ms [0.00s (infms/blk)]
                                   2020-04-26 11:56:43.188410 Checking mempool with 0 transactions and 0 inputs
                                   2020-04-26 11:56:43.188554 mapBlockIndex.size() = 1
                                   2020-04-26 11:56:43.188629 Failed to open mempool file from disk. Continuing anyway.
                                   2020-04-26 11:56:43.188697 nBestHeight = 0
                                   2020-04-26 11:56:43.188944 torcontrol thread start
                                   2020-04-26 11:56:43.189144 Bound to [::]:18444
                                   2020-04-26 11:56:43.189301 Bound to 0.0.0.0:18444
                                   2020-04-26 11:56:43.189389 init message: Loading P2P addresses...
                                   2020-04-26 11:56:43.189446 tor: Error connecting to Tor control socket
                                   2020-04-26 11:56:43.189495 ERROR: DeserializeFileDB: Failed to open file /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node1/regtest/peers.dat
                                   2020-04-26 11:56:43.189547 tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
                                   2020-04-26 11:56:43.189646 Invalid or missing peers.dat; recreating
                                   2020-04-26 11:56:43.202629 Flushed 0 addresses to peers.dat  13ms
                                   2020-04-26 11:56:43.202713 init message: Loading banlist...
                                   2020-04-26 11:56:43.202816 ERROR: DeserializeFileDB: Failed to open file /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node1/regtest/banlist.dat
                                   2020-04-26 11:56:43.202860 Invalid or missing banlist.dat; recreating
                                   2020-04-26 11:56:43.218546 Flushed 0 banned node ips/subnets to banlist.dat  16ms
                                   2020-04-26 11:56:43.218631 init message: Starting network threads...
                                   2020-04-26 11:56:43.218829 net thread start
                                   2020-04-26 11:56:43.218835 addcon thread start
                                   2020-04-26 11:56:43.218957 msghand thread start
                                   2020-04-26 11:56:43.218879 opencon thread start
                                   2020-04-26 11:56:43.218931 dnsseed thread start
                                   2020-04-26 11:56:43.218862 init message: Done loading
                                   2020-04-26 11:56:43.219106 Loading addresses from DNS seeds (could take a while)
                                   2020-04-26 11:56:43.219154 0 addresses found from DNS seeds
                                   2020-04-26 11:56:43.219195 dnsseed thread exit
                                   2020-04-26 11:56:44.190918 tor: Error connecting to Tor control socket
                                   2020-04-26 11:56:44.191008 tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
                                   2020-04-26 11:56:45.230628 Flushing wallet.dat
                                   2020-04-26 11:56:45.279563 Flushed wallet.dat 49ms
                                   2020-04-26 11:56:45.693318 tor: Error connecting to Tor control socket
                                   2020-04-26 11:56:45.693431 tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
                                   2020-04-26 11:56:47.948601 tor: Error connecting to Tor control socket
                                   2020-04-26 11:56:47.948716 tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
                                   2020-04-26 11:56:51.328746 tor: Error connecting to Tor control socket
                                   2020-04-26 11:56:51.328855 tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
                                   2020-04-26 11:56:56.391857 tor: Error connecting to Tor control socket
                                   2020-04-26 11:56:56.393227 tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
                                   2020-04-26 11:57:03.989212 tor: Error connecting to Tor control socket
                                   2020-04-26 11:57:03.990166 tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
                                   2020-04-26 11:57:15.386022 tor: Error connecting to Tor control socket
                                   2020-04-26 11:57:15.387224 tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
                                   2020-04-26 11:57:32.475315 tor: Error connecting to Tor control socket
                                   2020-04-26 11:57:32.480111 tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
 test  2020-04-26T11:56:40.774000Z TestFramework (DEBUG): PRNG seed is: 5125992667073647060 
 test  2020-04-26T11:56:40.775000Z TestFramework (DEBUG): Setting up network thread 
 test  2020-04-26T11:56:40.776000Z TestFramework (INFO): Initializing test directory /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7 
 test  2020-04-26T11:56:40.783000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up 
 test  2020-04-26T11:56:40.791000Z TestFramework.node1 (DEBUG): bitcoind started, waiting for RPC to come up 
 node0 2020-04-26T11:56:40.923809Z [init] Bitcoin Core version v0.20.99.0-65276c773-dirty (release build) 
 node0 2020-04-26T11:56:40.923848Z [init] InitParameterInteraction: parameter interaction: -bind set -> setting -listen=1 
 node0 2020-04-26T11:56:40.924194Z [init] Validating signatures for all blocks. 
 node0 2020-04-26T11:56:40.924216Z [init] Setting nMinimumChainWork=0000000000000000000000000000000000000000000000000000000000000000 
 node0 2020-04-26T11:56:40.928347Z [init] Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation 
 node0 2020-04-26T11:56:40.928406Z [init] Using RdSeed as additional entropy source 
 node0 2020-04-26T11:56:40.928435Z [init] Using RdRand as an additional entropy source 
 node0 2020-04-26T11:56:40.982665Z [init] Default data directory /Users/brakmic/Library/Application Support/Bitcoin 
 node0 2020-04-26T11:56:40.982703Z [init] Using data directory /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node0/regtest 
 node0 2020-04-26T11:56:40.982761Z [init] Config file: /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node0/bitcoin.conf 
 node0 2020-04-26T11:56:40.982807Z [init] Config file arg: regtest="1" 
 node0 2020-04-26T11:56:40.982837Z [init] Config file arg: [regtest] bind="127.0.0.1" 
 node0 2020-04-26T11:56:40.982863Z [init] Config file arg: [regtest] discover="0" 
 node0 2020-04-26T11:56:40.982888Z [init] Config file arg: [regtest] dnsseed="0" 
 node0 2020-04-26T11:56:40.982913Z [init] Config file arg: [regtest] fallbackfee="0.0002" 
 node0 2020-04-26T11:56:40.982938Z [init] Config file arg: [regtest] keypool="1" 
 node0 2020-04-26T11:56:40.982962Z [init] Config file arg: [regtest] listenonion="0" 
 node0 2020-04-26T11:56:40.982986Z [init] Config file arg: [regtest] port="11794" 
 node0 2020-04-26T11:56:40.983010Z [init] Config file arg: [regtest] printtoconsole="0" 
 node0 2020-04-26T11:56:40.983037Z [init] Config file arg: [regtest] rpcport="16794" 
 node0 2020-04-26T11:56:40.983063Z [init] Config file arg: [regtest] server="1" 
 node0 2020-04-26T11:56:40.983089Z [init] Config file arg: [regtest] shrinkdebugfile="0" 
 node0 2020-04-26T11:56:40.983113Z [init] Config file arg: [regtest] upnp="0" 
 node0 2020-04-26T11:56:40.983137Z [init] Command-line arg: addresstype="bech32" 
 node0 2020-04-26T11:56:40.983166Z [init] Command-line arg: datadir="/var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node0" 
 node0 2020-04-26T11:56:40.983191Z [init] Command-line arg: debug="" 
 node0 2020-04-26T11:56:40.983216Z [init] Command-line arg: debugexclude="libevent" 
 node0 2020-04-26T11:56:40.983240Z [init] Command-line arg: debugexclude="leveldb" 
 node0 2020-04-26T11:56:40.983265Z [init] Command-line arg: logthreadnames="" 
 node0 2020-04-26T11:56:40.983288Z [init] Command-line arg: logtimemicros="" 
 node0 2020-04-26T11:56:40.983313Z [init] Command-line arg: uacomment="testnode0" 
 node0 2020-04-26T11:56:40.983343Z [init] Using at most 125 automatic connections (8192 file descriptors available) 
 node0 2020-04-26T11:56:40.994110Z [init] Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements 
 node0 2020-04-26T11:56:41.003876Z [init] Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements 
 node0 2020-04-26T11:56:41.003957Z [init] Script verification uses 3 additional threads 
 node0 2020-04-26T11:56:41.004165Z [scheduler] scheduler thread start 
 node0 2020-04-26T11:56:41.004744Z [init] Allowing HTTP connections from: 127.0.0.0/8 ::1/128 
 node0 2020-04-26T11:56:41.005055Z [init] Binding RPC on address ::1 port 16794 
 node0 2020-04-26T11:56:41.008333Z [init] Binding RPC on address 127.0.0.1 port 16794 
 node0 2020-04-26T11:56:41.008428Z [init] Initialized HTTP server 
 node0 2020-04-26T11:56:41.008453Z [init] HTTP: creating work queue of depth 16 
 node0 2020-04-26T11:56:41.008475Z [init] Starting RPC 
 node0 2020-04-26T11:56:41.008506Z [init] Starting HTTP RPC server 
 node0 2020-04-26T11:56:41.008521Z [init] No rpcpassword set - using random cookie authentication. 
 node0 2020-04-26T11:56:41.008943Z [init] Generated RPC authentication cookie /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node0/regtest/.cookie 
 node0 2020-04-26T11:56:41.008971Z [init] Registering HTTP handler for / (exactmatch 1) 
 node0 2020-04-26T11:56:41.008989Z [init] Registering HTTP handler for /wallet/ (exactmatch 0) 
 node0 2020-04-26T11:56:41.009025Z [init] Starting HTTP server 
 node0 2020-04-26T11:56:41.009037Z [init] HTTP: starting 4 worker threads 
 node0 2020-04-26T11:56:41.009117Z [http] Entering http event loop 
 node0 2020-04-26T11:56:41.009166Z [init] Using wallet directory /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node0/regtest/wallets 
 node0 2020-04-26T11:56:41.009196Z [init] init message: Verifying wallet(s)... 
 node0 2020-04-26T11:56:41.009354Z [init] Using BerkeleyDB version Berkeley DB 4.8.30: (April  9, 2010) 
 node0 2020-04-26T11:56:41.009370Z [init] Using wallet /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node0/regtest/wallets 
 node0 2020-04-26T11:56:41.009605Z [init] BerkeleyEnvironment::Open: LogDir=/var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node0/regtest/wallets/database ErrorFile=/var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node0/regtest/wallets/db.log 
 node0 2020-04-26T11:56:41.078384Z [init] init message: Loading banlist... 
 node0 2020-04-26T11:56:41.078448Z [init] ERROR: DeserializeFileDB: Failed to open file /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node0/regtest/banlist.dat 
 node0 2020-04-26T11:56:41.078463Z [init] Invalid or missing banlist.dat; recreating 
 node0 2020-04-26T11:56:41.080432Z [http] Received a POST request for / from 127.0.0.1:55700 
 node0 2020-04-26T11:56:41.080535Z [httpworker.0] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2020-04-26T11:56:41.098750Z [init] Flushed 0 banned node ips/subnets to banlist.dat  20ms 
 node0 2020-04-26T11:56:41.099105Z [init] net: setting try another outbound peer=false 
 node0 2020-04-26T11:56:41.105230Z [init] Using /16 prefix for IP bucketing 
 node0 2020-04-26T11:56:41.105288Z [init] Cache configuration: 
 node0 2020-04-26T11:56:41.105369Z [init] * Using 2.0 MiB for block index database 
 node0 2020-04-26T11:56:41.105405Z [init] * Using 8.0 MiB for chain state database 
 node0 2020-04-26T11:56:41.105441Z [init] * Using 440.0 MiB for in-memory UTXO set (plus up to 286.1 MiB of unused mempool space) 
 node0 2020-04-26T11:56:41.105462Z [init] init message: Loading block index... 
 node0 2020-04-26T11:56:41.105497Z [init] Switching active chainstate to Chainstate [ibd] @ height -1 (null) 
 node0 2020-04-26T11:56:41.105848Z [init] Opening LevelDB in /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node0/regtest/blocks/index 
 node0 2020-04-26T11:56:41.215067Z [init] Opened LevelDB successfully 
 node0 2020-04-26T11:56:41.215116Z [init] Using obfuscation key for /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node0/regtest/blocks/index: 0000000000000000 
 node0 2020-04-26T11:56:41.215156Z [init] LoadBlockIndexDB: last block file = 0 
 node0 2020-04-26T11:56:41.215179Z [init] LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=0, size=0, heights=0...0, time=1970-01-01...1970-01-01) 
 node0 2020-04-26T11:56:41.215192Z [init] Checking all blk files are present... 
 node0 2020-04-26T11:56:41.215209Z [init] Initializing databases... 
 node0 2020-04-26T11:56:41.215385Z [init] Pre-allocating up to position 0x1000000 in blk00000.dat 
 node0 2020-04-26T11:56:41.281411Z [init] Initializing chainstate Chainstate [ibd] @ height -1 (null) 
 node0 2020-04-26T11:56:41.281659Z [init] Opening LevelDB in /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node0/regtest/chainstate 
 node0 2020-04-26T11:56:41.334044Z [http] Received a POST request for / from 127.0.0.1:55701 
 node0 2020-04-26T11:56:41.348092Z [httpworker.1] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2020-04-26T11:56:41.388851Z [init] Opened LevelDB successfully 
 node0 2020-04-26T11:56:41.389060Z [init] Wrote new obfuscate key for /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node0/regtest/chainstate: 73c001bc6fb0d573 
 node0 2020-04-26T11:56:41.389100Z [init] Using obfuscation key for /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node0/regtest/chainstate: 73c001bc6fb0d573 
 node0 2020-04-26T11:56:41.389177Z [init] init message: Rewinding blocks... 
 node0 2020-04-26T11:56:41.389220Z [init]  block index             284ms 
 node0 2020-04-26T11:56:41.389377Z [init] init message: Loading wallet... 
 node0 2020-04-26T11:56:41.389785Z [init] BerkeleyEnvironment::Open: LogDir=/var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node0/regtest/wallets/database ErrorFile=/var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node0/regtest/wallets/db.log 
 node0 2020-04-26T11:56:41.537808Z [init] [default wallet] Wallet File Version = 10500 
 node0 2020-04-26T11:56:41.538110Z [init] [default wallet] Keys: 0 plaintext, 0 encrypted, 0 w/ metadata, 0 total. Unknown wallet records: 0 
 node0 2020-04-26T11:56:41.613654Z [http] Received a POST request for / from 127.0.0.1:55702 
 node0 2020-04-26T11:56:41.613824Z [httpworker.3] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2020-04-26T11:56:41.772833Z [init] [default wallet] keypool added 2 keys (1 internal), size=2 (1 internal) 
 node0 2020-04-26T11:56:41.810418Z [init] [default wallet] LegacyScriptPubKeyMan::NewKeyPool rewrote keypool 
 node0 2020-04-26T11:56:41.845649Z [init] [default wallet] Wallet completed loading in             456ms 
 node0 2020-04-26T11:56:41.845860Z [init] [default wallet] setKeyPool.size() = 2 
 node0 2020-04-26T11:56:41.845953Z [init] [default wallet] mapWallet.size() = 0 
 node0 2020-04-26T11:56:41.845983Z [init] [default wallet] m_address_book.size() = 0 
 node0 2020-04-26T11:56:41.846755Z [loadblk]   - Load block from disk: 0.32ms [0.00s] 
 node0 2020-04-26T11:56:41.846863Z [loadblk] BlockChecked: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 state=Valid 
 node0 2020-04-26T11:56:41.846914Z [loadblk]   - Connect total: 0.17ms [0.00s (0.17ms/blk)] 
 node0 2020-04-26T11:56:41.846948Z [loadblk]   - Flush: 0.04ms [0.00s (0.04ms/blk)] 
 node0 2020-04-26T11:56:41.846992Z [loadblk]   - Writing chainstate: 0.04ms [0.00s (0.04ms/blk)] 
 node0 2020-04-26T11:56:41.847079Z [loadblk] UpdateTip: new best=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 height=0 version=0x00000001 log2_work=1 tx=1 date='2011-02-02T23:16:42Z' progress=1.000000 cache=0.0MiB(0txo) 
 node0 2020-04-26T11:56:41.847111Z [loadblk]   - Connect postprocess: 0.12ms [0.00s (0.12ms/blk)] 
 node0 2020-04-26T11:56:41.847138Z [loadblk] - Connect block: 0.68ms [0.00s (0.68ms/blk)] 
 node0 2020-04-26T11:56:41.847177Z [loadblk] Checking mempool with 0 transactions and 0 inputs 
 node0 2020-04-26T11:56:41.847234Z [loadblk] Enqueuing BlockConnected: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 block height=0 
 node0 2020-04-26T11:56:41.847293Z [loadblk] Enqueuing UpdatedBlockTip: new block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 fork block hash=null (in IBD=true) 
 node0 2020-04-26T11:56:41.847367Z [scheduler] BlockConnected: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 block height=0 
 node0 2020-04-26T11:56:41.847450Z [init] block tree size = 1 
 node0 2020-04-26T11:56:41.847583Z [init] nBestHeight = 0 
 node0 2020-04-26T11:56:41.847657Z [loadblk] Failed to open mempool file from disk. Continuing anyway. 
 node0 2020-04-26T11:56:41.847738Z [scheduler] UpdatedBlockTip: new block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 fork block hash=null (in IBD=true) 
 node0 2020-04-26T11:56:41.847878Z [init] Bound to 127.0.0.1:11794 
 node0 2020-04-26T11:56:41.847934Z [init] init message: Loading P2P addresses... 
 node0 2020-04-26T11:56:41.848032Z [init] ERROR: DeserializeFileDB: Failed to open file /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node0/regtest/peers.dat 
 node0 2020-04-26T11:56:41.848169Z [init] Invalid or missing peers.dat; recreating 
 node0 2020-04-26T11:56:41.861490Z [init] Flushed 0 addresses to peers.dat  13ms 
 node0 2020-04-26T11:56:41.861573Z [init] init message: Starting network threads... 
 node0 2020-04-26T11:56:41.861721Z [init] DNS seeding disabled 
 node0 2020-04-26T11:56:41.861901Z [init] init message: Done loading 
 node0 2020-04-26T11:56:41.863198Z [addcon] addcon thread start 
 node0 2020-04-26T11:56:41.863327Z [net] net thread start 
 node0 2020-04-26T11:56:41.863459Z [msghand] msghand thread start 
 node0 2020-04-26T11:56:41.863568Z [opencon] opencon thread start 
 node0 2020-04-26T11:56:41.868413Z [http] Received a POST request for / from 127.0.0.1:55703 
 node0 2020-04-26T11:56:41.868583Z [httpworker.2] ThreadRPCServer method=getblockcount user=__cookie__ 
 test  2020-04-26T11:56:41.869000Z TestFramework.node0 (DEBUG): RPC successfully started 
 node0 2020-04-26T11:56:44.375789Z [scheduler] Flushing wallet.dat 
 node0 2020-04-26T11:56:44.416852Z [scheduler] Flushed wallet.dat 41ms 
 node0 2020-04-26T11:57:41.009682Z [scheduler] Feeding 308 bytes of dynamic environment data into RNG 
 node0 2020-04-26T11:57:42.173548Z [opencon] Adding fixed seed nodes as DNS doesn't seem to be available. 
 test  2020-04-26T11:57:42.914000Z TestFramework.node0 (DEBUG): Stopping node 
 node0 2020-04-26T11:57:42.917544Z [http] Received a POST request for / from 127.0.0.1:55978 
 node0 2020-04-26T11:57:42.917698Z [httpworker.0] ThreadRPCServer method=stop user=__cookie__ 
 test  2020-04-26T11:57:42.918000Z TestFramework.node1 (DEBUG): Stopping node 
 test  2020-04-26T11:57:42.919000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/Users/brakmic/projects/bitcoin-dev/btc-master/test/functional/test_framework/test_framework.py", line 434, in start_nodes
                                       node.wait_for_rpc_connection()
                                     File "/Users/brakmic/projects/bitcoin-dev/btc-master/test/functional/test_framework/test_node.py", line 245, in wait_for_rpc_connection
                                       self._raise_assertion_error("Unable to connect to bitcoind after {}s".format(self.rpc_timeout))
                                     File "/Users/brakmic/projects/bitcoin-dev/btc-master/test/functional/test_framework/test_node.py", line 158, in _raise_assertion_error
                                       raise AssertionError(self._node_msg(msg))
                                   AssertionError: [node 1] Unable to connect to bitcoind after 60s
                                   During handling of the above exception, another exception occurred:
                                   Traceback (most recent call last):
                                     File "/Users/brakmic/projects/bitcoin-dev/btc-master/test/functional/test_framework/test_framework.py", line 111, in main
                                       self.setup()
                                     File "/Users/brakmic/projects/bitcoin-dev/btc-master/test/functional/test_framework/test_framework.py", line 226, in setup
                                       self.setup_network()
                                     File "/Users/brakmic/projects/bitcoin-dev/btc-master/test/functional/test_framework/test_framework.py", line 315, in setup_network
                                       self.setup_nodes()
                                     File "./test/functional/wallet_upgradewallet.py", line 56, in setup_nodes
                                       self.start_nodes()
                                     File "/Users/brakmic/projects/bitcoin-dev/btc-master/test/functional/test_framework/test_framework.py", line 437, in start_nodes
                                       self.stop_nodes()
                                     File "/Users/brakmic/projects/bitcoin-dev/btc-master/test/functional/test_framework/test_framework.py", line 453, in stop_nodes
                                       node.stop_node(wait=wait)
                                     File "/Users/brakmic/projects/bitcoin-dev/btc-master/test/functional/test_framework/test_node.py", line 284, in stop_node
                                       self.stop()
                                     File "/Users/brakmic/projects/bitcoin-dev/btc-master/test/functional/test_framework/test_node.py", line 175, in __getattr__
                                       assert self.rpc_connected and self.rpc is not None, self._node_msg("Error: no RPC connection")
                                   AssertionError: [node 1] Error: no RPC connection
 test  2020-04-26T11:57:42.926000Z TestFramework (DEBUG): Closing down network thread 
 test  2020-04-26T11:57:42.978000Z TestFramework (INFO): Stopping nodes 
 test  2020-04-26T11:57:42.979000Z TestFramework.node0 (DEBUG): Stopping node 
 node0 2020-04-26T11:57:42.979833Z [http] Received a POST request for / from 127.0.0.1:55979 
 node0 2020-04-26T11:57:42.979945Z [httpworker.1] ThreadRPCServer method=stop user=__cookie__ 

There are four cases that might continue the loop for 60 seconds. Can you add print statements to check which one it is?

            except JSONRPCException as e:  # Initialization phase
                # -28 RPC in warmup
                # -342 Service unavailable, RPC server started but is shutting down due to error
                if e.error['code'] != -28 and e.error['code'] != -342:
                    raise  # unknown JSON RPC exception
            except ConnectionResetError:
                # This might happen when the RPC server is in warmup, but shut down before the call to getblockcount
                # succeeds. Try again to properly raise the FailedToStartError
                pass
            except OSError as e:
                if e.errno != errno.ECONNREFUSED:  # Port not yet open?
                    raise  # unknown OS error
            except ValueError as e:  # cookie file not found and no rpcuser or rpcpassword; bitcoind is still starting
                if "No RPC credentials" not in str(e):
                    raise

When I add print's to it I get this while running the test:

./test/functional/wallet_upgradewallet.py                                                     (736ms)  
2020-04-26T12:16:28.456000Z TestFramework (INFO): Initializing test directory /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_c8qst9si
EXCEPTION: ValueError No RPC credentials
EXCEPTION: ValueError No RPC credentials
EXCEPTION: JSONRPCException Loading block index... (-28)
EXCEPTION: JSONRPCException Loading wallet... (-28)
EXCEPTION: JSONRPCException Loading wallet... (-28)
EXCEPTION: [Errno 61] Connection refused
EXCEPTION: [Errno 61] Connection refused
EXCEPTION: [Errno 61] Connection refused
EXCEPTION: [Errno 61] Connection refused

And it continues like that.

So

• the node starts correctly
• the authproxy has the right credentials
• ?

It seems to be using the default ports. Can you try with this:

diff --git a/test/functional/test_framework/util.py b/test/functional/test_framework/util.py
index 64e1aa3bbc..65cb7ffb7a 100644
--- a/test/functional/test_framework/util.py
+++ b/test/functional/test_framework/util.py
@@ -310,7 +310,7 @@ def initialize_datadir(dirname, n, chain):
         chain_name_conf_section = chain
     with open(os.path.join(datadir, "bitcoin.conf"), 'w', encoding='utf8') as f:
         f.write("{}=1\n".format(chain_name_conf_arg))
-        f.write("[{}]\n".format(chain_name_conf_section))
+        #f.write("[{}]\n".format(chain_name_conf_section))
         f.write("port=" + str(p2p_port(n)) + "\n")
         f.write("rpcport=" + str(rpc_port(n)) + "\n")
         f.write("fallbackfee=0.0002\n")

So

• the node starts correctly
• the authproxy has the right credentials
• ?

Not sure about credentials as I am using v0.16.3 the same way as with newer nodes from ./test/functional/feature_backwards_compatibility.py. Basically, I downloaded the binary with previous_release.sh, then given the paths to self.add_nodes and hoped it'd start it the same way it did with other nodes.

It seems to be using the default ports. Can you try with this:

diff --git a/test/functional/test_framework/util.py b/test/functional/test_framework/util.py
index 64e1aa3bbc..65cb7ffb7a 100644
--- a/test/functional/test_framework/util.py
+++ b/test/functional/test_framework/util.py
@@ -310,7 +310,7 @@ def initialize_datadir(dirname, n, chain):
         chain_name_conf_section = chain
     with open(os.path.join(datadir, "bitcoin.conf"), 'w', encoding='utf8') as f:
         f.write("{}=1\n".format(chain_name_conf_arg))
-        f.write("[{}]\n".format(chain_name_conf_section))
+        #f.write("[{}]\n".format(chain_name_conf_section))
         f.write("port=" + str(p2p_port(n)) + "\n")
         f.write("rpcport=" + str(rpc_port(n)) + "\n")
         f.write("fallbackfee=0.0002\n")

Have tried it, same error: no rpc credentials:

2020-04-26T12:58:29.540000Z TestFramework (INFO): Initializing test directory /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_zq4ik840
EXCEPTION: ValueError No RPC credentials
2020-04-26T12:58:29.808000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/Users/brakmic/projects/bitcoin-dev/btc-master/test/functional/test_framework/test_framework.py", line 434, in start_nodes
    node.wait_for_rpc_connection()
  File "/Users/brakmic/projects/bitcoin-dev/btc-master/test/functional/test_framework/test_node.py", line 217, in wait_for_rpc_connection
    'bitcoind exited with status {} during initialization'.format(self.process.returncode)))
test_framework.test_node.FailedToStartError: [node 0] bitcoind exited with status 1 during initialization

During handling of the above exception, another exception occurred:

This is not the same error. The previous error was EXCEPTION: [Errno 61] Connection refused.

This is the excerpt from the 0.16 debug log:

                                   2020-04-26 11:56:40.864468 Allowing HTTP connections from: 127.0.0.0/8 ::1/128 
                                   2020-04-26 11:56:40.866260 Binding RPC on address ::1 port 18443
                                   2020-04-26 11:56:40.872933 Binding RPC on address 127.0.0.1 port 18443
                                   2020-04-26 11:56:40.873025 Initialized HTTP server
                                   2020-04-26 11:56:40.873054 HTTP: creating work queue of depth 16
                                   2020-04-26 11:56:40.873075 Starting RPC
                                   2020-04-26 11:56:40.873113 Starting HTTP RPC server
                                   2020-04-26 11:56:40.873134 No rpcpassword set - using random cookie authentication
                                   2020-04-26 11:56:40.873470 Generated RPC authentication cookie /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node1/regtest/.cookie
                                   2020-04-26 11:56:40.873508 Registering HTTP handler for / (exactmatch 1)
                                   2020-04-26 11:56:40.873532 Registering HTTP handler for /wallet/ (exactmatch 0)
                                   2020-04-26 11:56:40.873558 Starting HTTP server

You want it to use the right rpc_port

This is the excerpt from the 0.16 debug log:

                                   2020-04-26 11:56:40.864468 Allowing HTTP connections from: 127.0.0.0/8 ::1/128 
                                   2020-04-26 11:56:40.866260 Binding RPC on address ::1 port 18443
                                   2020-04-26 11:56:40.872933 Binding RPC on address 127.0.0.1 port 18443
                                   2020-04-26 11:56:40.873025 Initialized HTTP server
                                   2020-04-26 11:56:40.873054 HTTP: creating work queue of depth 16
                                   2020-04-26 11:56:40.873075 Starting RPC
                                   2020-04-26 11:56:40.873113 Starting HTTP RPC server
                                   2020-04-26 11:56:40.873134 No rpcpassword set - using random cookie authentication
                                   2020-04-26 11:56:40.873470 Generated RPC authentication cookie /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node1/regtest/.cookie
                                   2020-04-26 11:56:40.873508 Registering HTTP handler for / (exactmatch 1)
                                   2020-04-26 11:56:40.873532 Registering HTTP handler for /wallet/ (exactmatch 0)
                                   2020-04-26 11:56:40.873558 Starting HTTP server

You want it to use the right rpc_port

I actually hoped, it would do it without any additional config. My problem is: what to do to make v0.16.3 run with the test_framework.

I have no idea why 0.16.3 is not picking up the -rpcport setting.

What is

cat  /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_foobar/node1/bitcoin.conf
./releases_path/v0.16.3/bin/bitcoind -datadir=/var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_foobar/node1/
^C

I have no idea why 0.16.3 is not picking up the -rpcport setting.

What is

cat  /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_foobar/node1/bitcoin.conf
./releases_path/v0.16.3/bin/bitcoind -datadir=/var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_foobar/node1/
^C

This is the content of node1's bitcoin.conf, which is the v0.16.3 node on my machine. The rpcport is there:

cat /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_jdbyq_69/node1/bitcoin.conf 
regtest=1
port=12391
rpcport=17391
fallbackfee=0.0002
server=1
keypool=1
discover=0
dnsseed=0
listenonion=0
printtoconsole=0
upnp=0
shrinkdebugfile=0
bind=127.0.0.1

Maybe v0.16.3 doesn't read this bitcoin.conf automatically (for whatever reason). Maybe we should try starting it with explicit --conf=path_to_conf.

Just speculating.

It does use it:

                                   2020-04-26 11:56:40.843422 Using config file /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node1/bitcoin.conf

It does use it:

                                   2020-04-26 11:56:40.843422 Using config file /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_7nf60xj7/node1/bitcoin.conf

Well, then we have entered the weird reasons territory. :)

When I add this to util.py

f.write("rpcuser=dummy\n")
f.write("rpcpassword=dummypwd\n")

I get this error:

./test/functional/wallet_upgradewallet.py                                                 (775ms) │
2020-04-26T13:21:53.390000Z TestFramework (INFO): Initializing test directory /var/folders/7q/4ffytzk562dd2ky4bfg9_w7h0000gn/T/bitcoin_func_test_8knpfnb1
EXCEPTION: [Errno 61] Connection refused
2020-04-26T13:21:53.670000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):

No more no RPC credentials.

Works for me:

root@d016acdaf338:/# batcat /tmp/node1/bitcoin.conf 
───────┬────────────────────────────────────────────────────────────────────────────────────────────────────────────
       │ File: /tmp/node1/bitcoin.conf
───────┼────────────────────────────────────────────────────────────────────────────────────────────────────────────
   1   │ regtest=1
   2   │ port=12391
   3   │ rpcport=17391
   4   │ fallbackfee=0.0002
   5   │ server=1
   6   │ keypool=1
   7   │ discover=0
   8   │ dnsseed=0
   9   │ listenonion=0
  10   │ printtoconsole=0
  11   │ upnp=0
  12   │ shrinkdebugfile=0
  13   │ bind=127.0.0.1
───────┴────────────────────────────────────────────────────────────────────────────────────────────────────────────
root@d016acdaf338:/# ./bitcoin-0.16.3/bin/bitcoind -datadir=/tmp/node1/ -printtoconsole -debug|grep 'RPC on address'
2020-04-26 14:52:40 Binding RPC on address ::1 port 17391
2020-04-26 14:52:40 Binding RPC on address 127.0.0.1 port 17391
^C

So the section is the issue:

root@d016acdaf338:/# batcat /tmp/node1/bitcoin.conf 
───────┬────────────────────────────────────────────────────────────────────────────────────────────────────────────
       │ File: /tmp/node1/bitcoin.conf
───────┼────────────────────────────────────────────────────────────────────────────────────────────────────────────
   1   │ regtest=1
   2   │ [regtest]
   3   │ port=12391
   4   │ rpcport=17391
   5   │ fallbackfee=0.0002
   6   │ server=1
   7   │ keypool=1
   8   │ discover=0
   9   │ dnsseed=0
  10   │ listenonion=0
  11   │ printtoconsole=0
  12   │ upnp=0
  13   │ shrinkdebugfile=0
  14   │ bind=127.0.0.1
───────┴────────────────────────────────────────────────────────────────────────────────────────────────────────────
root@d016acdaf338:/# ./bitcoin-0.16.3/bin/bitcoind -datadir=/tmp/node1/ -printtoconsole -debug|grep 'RPC on address'
2020-04-26 14:53:48 Binding RPC on address ::1 port 18443
2020-04-26 14:53:48 Binding RPC on address 127.0.0.1 port 18443
^C

So before you start the 0.16.3 node, remove this line from the bitcoin.conf:

#18767 (comment)

So it would make sense to provide a fix for the section issue first?

It will be fine if you do it in the same pull request.

It will be fine if you do it in the same pull request.

Ok, no problem. Will fix it there and then rewrite the test. That is, will use my original solution that didn't work.

Thanks for helping me out!

One question regarding fixing of util.py:

As I don't see any option to check for bitcoind version that should read those settings, I am applying this cheap trick to make old bitcoind's accept port/rpcport settings:

diff --git a/test/functional/test_framework/util.py b/test/functional/test_framework/util.py
index 64e1aa3bb..44d1c8509 100644
--- a/test/functional/test_framework/util.py
+++ b/test/functional/test_framework/util.py
@@ -310,6 +310,8 @@ def initialize_datadir(dirname, n, chain):
         chain_name_conf_section = chain
     with open(os.path.join(datadir, "bitcoin.conf"), 'w', encoding='utf8') as f:
         f.write("{}=1\n".format(chain_name_conf_arg))
+        f.write("port=" + str(p2p_port(n)) + "\n")
+        f.write("rpcport=" + str(rpc_port(n)) + "\n")
         f.write("[{}]\n".format(chain_name_conf_section))
         f.write("port=" + str(p2p_port(n)) + "\n")
         f.write("rpcport=" + str(rpc_port(n)) + "\n")

So, I'm just putting these two settings above the section name. Old bitcoind's would read them and ignore the rest, while new ones would simply ignore redundant entries.

However, not sure if this is the cleanest approach. Is there a way to find out the node version?

I could try to expand the initialize_datadir function, but this seems to be a bit too invasive, imo.

My tests with the now rewritten wallet_upgradewallet.py are successful, v0.16.3 bitcoind runs without any problems.