Inconsistency in listsinceblock between lastblock and confirmations

[shesek]

It seems like issuing listsinceblock rpc calls while bitcoind is processing blocks can result in lastblock and confirmations values that disagree with each-other -- the number of confirmations is not relative to the lastblock.

I'm able to reliably reproduce this by issuing listsinceblock calls from a blocknotify handler. Here's a reproduction script:

#!/bin/bash
shopt -s expand_aliases
trap 'bcli stop' SIGINT SIGTERM EXIT

DIR=/tmp/test-bitcoin
rm -rf $DIR && mkdir $DIR

bopt="-regtest -datadir=$DIR -rpcport=8763"
alias bcli="bitcoin-cli $bopt"
alias miner="bcli -rpcwallet=miner"
alias wallet="bcli -rpcwallet=wallet"

# Mine some coins without triggering `blocknotify` 
bitcoind $bopt -nolisten -daemon -wallet=miner
miner generatetoaddress 101 `miner -rpcwait getnewaddress` > /dev/null
bcli stop && sleep 1

# Now start with `blocknotify` and create a separate wallet to avoid cluttering `listsinceblock` with mining-related txs
bitcoind $bopt -nolisten -daemon -wallet=miner -fallbackfee=0.00001 \
    -blocknotify="bitcoin-cli $bopt -rpcwallet=wallet listsinceblock | tee -a $DIR/notify.log"
bcli -rpcwait createwallet wallet

miner sendtoaddress `wallet getnewaddress` 1
miner generatetoaddress 20 `miner getnewaddress`

cat $DIR/notify.log | jq -c '{lastblock: .lastblock, tx: (.transactions[] | [.txid,.confirmations,.blockheight])}'

This is the output of the jq command on the last line of the script, with Bitcoin Core 0.20.0:

{"lastblock":"3d37a7b824a9250a87e78be88c1c58dcad737d4c43ddb1a1c6dea46e9a56b5ff","tx":["58cf095ffcd93ab838b6382435f1c9b7b8ea4daac8128c93a8b2d67b60715d16",4,102]}
{"lastblock":"7092dd077f8e6306ac649e7ebbb24d2b7840702b8a509a225912d7192bf8f3ae","tx":["58cf095ffcd93ab838b6382435f1c9b7b8ea4daac8128c93a8b2d67b60715d16",8,102]}
{"lastblock":"7092dd077f8e6306ac649e7ebbb24d2b7840702b8a509a225912d7192bf8f3ae","tx":["58cf095ffcd93ab838b6382435f1c9b7b8ea4daac8128c93a8b2d67b60715d16",8,102]}
{"lastblock":"2f1370f3efd68cad09131a3aa4d763c79e37c7253175db2e136089bfd24387ea","tx":["58cf095ffcd93ab838b6382435f1c9b7b8ea4daac8128c93a8b2d67b60715d16",9,102]}
{"lastblock":"2f1370f3efd68cad09131a3aa4d763c79e37c7253175db2e136089bfd24387ea","tx":["58cf095ffcd93ab838b6382435f1c9b7b8ea4daac8128c93a8b2d67b60715d16",12,102]}
{"lastblock":"2f1370f3efd68cad09131a3aa4d763c79e37c7253175db2e136089bfd24387ea","tx":["58cf095ffcd93ab838b6382435f1c9b7b8ea4daac8128c93a8b2d67b60715d16",12,102]}
{"lastblock":"4c2ccc8d0efda2d73a00a661f8fd7820bf60c59d8022894e63efb1d4f170c578","tx":["58cf095ffcd93ab838b6382435f1c9b7b8ea4daac8128c93a8b2d67b60715d16",13,102]}
{"lastblock":"4c2ccc8d0efda2d73a00a661f8fd7820bf60c59d8022894e63efb1d4f170c578","tx":["58cf095ffcd93ab838b6382435f1c9b7b8ea4daac8128c93a8b2d67b60715d16",14,102]}
{"lastblock":"4c2ccc8d0efda2d73a00a661f8fd7820bf60c59d8022894e63efb1d4f170c578","tx":["58cf095ffcd93ab838b6382435f1c9b7b8ea4daac8128c93a8b2d67b60715d16",15,102]}
{"lastblock":"4c2ccc8d0efda2d73a00a661f8fd7820bf60c59d8022894e63efb1d4f170c578","tx":["58cf095ffcd93ab838b6382435f1c9b7b8ea4daac8128c93a8b2d67b60715d16",15,102]}
{"lastblock":"4c2ccc8d0efda2d73a00a661f8fd7820bf60c59d8022894e63efb1d4f170c578","tx":["58cf095ffcd93ab838b6382435f1c9b7b8ea4daac8128c93a8b2d67b60715d16",15,102]}
{"lastblock":"4c2ccc8d0efda2d73a00a661f8fd7820bf60c59d8022894e63efb1d4f170c578","tx":["58cf095ffcd93ab838b6382435f1c9b7b8ea4daac8128c93a8b2d67b60715d16",15,102]}
{"lastblock":"635449428c88781cc80747a77b9c59d9f46263e6f606c8306b021116d32a8320","tx":["58cf095ffcd93ab838b6382435f1c9b7b8ea4daac8128c93a8b2d67b60715d16",16,102]}
{"lastblock":"412240b03e197502b228b95396d3d8386499ed5acf2a0ac30d08b34e798b7bf0","tx":["58cf095ffcd93ab838b6382435f1c9b7b8ea4daac8128c93a8b2d67b60715d16",18,102]}
{"lastblock":"54ea16118338039c672229f3834db8917cfc5b25b870c7db7d800587ea117895","tx":["58cf095ffcd93ab838b6382435f1c9b7b8ea4daac8128c93a8b2d67b60715d16",19,102]}
{"lastblock":"54ea16118338039c672229f3834db8917cfc5b25b870c7db7d800587ea117895","tx":["58cf095ffcd93ab838b6382435f1c9b7b8ea4daac8128c93a8b2d67b60715d16",19,102]}
{"lastblock":"181e7bbcee44402a67f171404611a3885238338555ab58039b1330249662f87f","tx":["58cf095ffcd93ab838b6382435f1c9b7b8ea4daac8128c93a8b2d67b60715d16",20,102]}

Notice how lastblock is reported as 4c2ccc8d.. with 13 confirmations for tx 58cf095f..., then later with 14 confirmations for the same block and tx, then later with 15.

You may need to generate more than 20 blocks if you're not able to catch this. For the tests I ran, it seems like 20 (or even 10) was sufficient.

[pstratem]

Indeed that appears to be a race condition.

To fix this either the function needs to detect the tip changing or it needs to hold cs_main.

[ryanofsky]

@shesek what version of bitcoin are you seeing this with? I think this issue should have been fixed by f7ba881 from #17954 (merged a few days after the 0.20 branch). Trying your reproduction script (nice script!) on current master 8ef15e8, I saw confirmations increase in lockstep with lastblock:

{"lastblock":"01a1db130aae8fe7c878dffa6cee4f6251b0a28bac42383a014e1fd0c845bdd9","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",3,102]}
{"lastblock":"57d422331f2d7f8dd66e5e52a2625f729368360bcee66f7ab647d466c0f3282c","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",4,102]}
{"lastblock":"57d422331f2d7f8dd66e5e52a2625f729368360bcee66f7ab647d466c0f3282c","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",4,102]}
{"lastblock":"47d5ea88afb4672c45c4087ed6cd1f13c6640c6a346bcbb1e2ba7f9e3aa24372","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",5,102]}
{"lastblock":"7bbb7c7141faced32c82f5760343a23a04ea7929e69cd3fefee41720d14fc69c","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",6,102]}
{"lastblock":"0f66cb1ecc1bed21b250a9bbb67623d9e7624fde44cdc12e947c48a40548f9b8","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",7,102]}
{"lastblock":"464fd253141187ca5293e633c61582c747a333bc5c56300c9c54f256462c896a","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",9,102]}
{"lastblock":"5d278017fad7d146c0fddc0600d70e112743524d3599c480366bcc89c75d4bab","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",10,102]}
{"lastblock":"6b69ec48239f2c4a9cec13f284501473329777825251ffaa73c7284f657a6d97","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",11,102]}
{"lastblock":"3e4c3929c89d7f2309d1e98636c252c8cdbbe4d0669dc8203042d4c24b679b7e","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",12,102]}
{"lastblock":"3e4c3929c89d7f2309d1e98636c252c8cdbbe4d0669dc8203042d4c24b679b7e","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",12,102]}
{"lastblock":"5b34d33d545e114301746236feda3abf5e7066c84b612e19d43f700aca724510","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",14,102]}
{"lastblock":"5b34d33d545e114301746236feda3abf5e7066c84b612e19d43f700aca724510","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",14,102]}
{"lastblock":"4a5750028b953ec523420b02bb5f9145c78acfb98ae816efb8bed8b0e8ac5d9c","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",17,102]}
{"lastblock":"4a5750028b953ec523420b02bb5f9145c78acfb98ae816efb8bed8b0e8ac5d9c","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",17,102]}
{"lastblock":"62ac4ab1fc763d8b583d6818568c96b907e9133119bda394f2f019536859d661","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",19,102]}
{"lastblock":"62ac4ab1fc763d8b583d6818568c96b907e9133119bda394f2f019536859d661","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",19,102]}
{"lastblock":"37b190f76332537692212da0302f4f78d4d8997983a35f8a906addc0a28977dc","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",20,102]}
{"lastblock":"37b190f76332537692212da0302f4f78d4d8997983a35f8a906addc0a28977dc","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",20,102]}
{"lastblock":"37b190f76332537692212da0302f4f78d4d8997983a35f8a906addc0a28977dc","tx":["a1ae1cc64e6b8f5e012af93ab227d41236d3ad671f20f50e53230936a66afe4d",20,102]}

re: #19338 (comment)

Indeed that appears to be a race condition.

To fix this either the function needs to detect the tip changing or it needs to hold cs_main.

I don't think these things are true. Wallet code shouldn't need to be concerned with node tip to report internally consistent results, and it shouldn't hold cs_main

[shesek]

@ryan52 This was with Bitcoin Core v0.20.0 (I added this to the issue description too, forgot to mention it earlier). I will give this a try with f7ba881 and report back.

It might also be worth trying this with 100 blocks or so and see if everything is still consistent.

[ryanofsky]

Retested master 8ef15e8 with 100 blocks and still didn't see the bug (didn't check exhaustively but piped jq output to uniq and checked visually the same lastblock hashes or confirmation numbers weren't repeated twice).

Also tested v0.20.0 tag a62f0ed and did see the bug (same lastblock hash repeated with different confirmation numbers).

Also confirmed bugfix commit f7ba881 from #17954 did not exhibit the bug and while parent commit bc96a9b did have the bug.

---

All this suggests f7ba881 from #17954 does fix this bug, which I'd expect, because this is exactly the type of inconsistency #17954 was intended to fix.

@shesek, it's be great if you could verify the fix not just to provide confirmation, but also to ensure the fix doesn't have it's own problems since listsinceblock output is more internally consistent now but also more detached from the node and potentially stale.

Another thing that's unclear is how important the bug is and whether it'd be useful to backport a fix. I'd think the behavior described was probably longstanding and not a regression. If a backport should be done, it might be worth only backporting commit f7ba881 and the new interfaces/chain methods it depends and not backporting all of #17954. That way the backport is strictly limited to the listsinceblock method and doesn't affect all the other parts of the wallet and gui that #17954 affects

[shesek]

I verified that this is no longer an issue against current master (e3fa3c7).

but also to ensure the fix doesn't have it's own problems since listsinceblock output is more internally consistent now but also more detached from the node and potentially stale.

It wouldn't be ideal if issuing listsinceblock following a blocknotify could return stale information that's not at least as recent as the notified chain tip (I'm using this for real-time indexing, this would mean that updates would get lost until the next periodic poll), but it appears that this is not the case -- the lastblock being returned is always at least as recent as the one received via the notification, so it all seems good.

I used this modified script to check both for consistent confirmations number (tx_height == tip_height-confirmations+1) and for the recency of the data compared to the notified tip.

Another thing that's unclear is how important the bug is and whether it'd be useful to backport a fix

At least for my specific case, I worked around the bug and don't mind it not being backported. But others using this might disagree...

[ryanofsky]

Thanks for checking and verifying that slightly more stale information returned by the fix doesn't cause problems for the external index. Also thanks for the new test script.

Since you have a workaround, and since this bug has probably been around a long time, and since backporting the fix requires breaking up #17954 or pulling in unrelated changes, I think I'd opt not to backport f7ba881 from #17954 right now. But we could reconsider if more problems are reported.

[shesek]

I'd opt not to backport f7ba881

Agreed, I think so too.

Thanks for helping diagnose this!