signet testing: transaction that was evicted from mempool and abandoned by sender wallet showed up as a new unconfirmed txn on sparrow recepient

[7hacker]

1. Start sparrow with -n signet -l DEBUG, there is currently one unconfirmed txn that is waiting indefinitely in the mempool since its fee is lower than allowed. This is seen as "Unconfirmed"

2. shutdown the signet bitcoind, disconnect sparrow from the bitcoin core
3. delete mempool.dat and restart signet bitcoind with -walletbroadcast=0
4. run abandontransaction on the sender's wallet to abandon the transaction completely
5. the mempool is now empty with 0 txns

~/code/bitcoin/src (master) $ ./bitcoin-cli -datadir=signet-custom -rpcwallet=test getmempoolinfo
{
  "loaded": true,
  "size": 0,
  "bytes": 0,
  "usage": 0,
  "total_fee": 0.00000000,
  "maxmempool": 300000000,
  "mempoolminfee": 0.00001000,
  "minrelaytxfee": 0.00001000,
  "unbroadcastcount": 0
}

6. sparrow's rpc calls logging correctly show that the prev txid is not found anymore

DEBUG bitcoincore_rpc                   > JSON-RPC request: getmempoolentry ["bbe825871e49a284d86f323238415d7d105c9f56a9bb9ed0c1a36606ad1903f8"]
 DEBUG bitcoincore_rpc                   > JSON-RPC error for getmempoolentry: RpcError { code: -5, message: "Transaction not in mempool", data: None }
 DEBUG bwt::indexer                      > failed fetching mempool entry for bbe825871e49a284d86f323238415d7d105c9f56a9bb9ed0c1a36606ad1903f8: JSON-RPC error: RPC error response: RpcError { code: -5, message: "Transaction not in mempool", data: None }

7. But sparrow's UI / client showed me a notification of a new unconfirmed txn that is incoming , and the below screenshot showing an 'unconfirmed parent'

I'm not sure if this is correct but assuming that no txn would ever come then this entry would be unncessary?

[craigraw]

Interesting test! On the one hand, it would be good to reflect what's in the user's mempool, and on the other, in the general case broadcasting a transaction means it can never truly be considered lost.

What happens when you refresh the wallet in this state (View menu)?

[7hacker]

1. View menu -> refresh wallet
2. Sparrow wallet disconnects from signetd bitcoin
3. Use the slider in bottom right to reconnect
4. Sparrow UI stalls, becomes unresponsive, and logs show:

 DEBUG bitcoincore_rpc                   > JSON-RPC request: getwalletinfo []
2021-03-11 20:15:14,281 ERROR Error in version check address
com.sparrowwallet.drongo.address.InvalidAddressException: Could not parse invalid address 1LiJx1HQ49L2LzhBwbgwXdHiGodvPg5YaV
        at com.sparrowwallet.drongo@0.9/com.sparrowwallet.drongo.address.Address.fromString(Address.java:132)
        at com.sparrowwallet.drongo@0.9/com.sparrowwallet.drongo.address.Address.fromString(Address.java:67)
        at com.sparrowwallet.sparrow@1.2.0/com.sparrowwallet.sparrow.net.VersionCheckService.verifySignature(VersionCheckService.java:68)
        at com.sparrowwallet.sparrow@1.2.0/com.sparrowwallet.sparrow.net.VersionCheckService$1.call(VersionCheckService.java:35)
        at com.sparrowwallet.sparrow@1.2.0/com.sparrowwallet.sparrow.net.VersionCheckService$1.call(VersionCheckService.java:31)
        at javafx.graphics/javafx.concurrent.Task$TaskCallable.call(Task.java:1425)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at javafx.graphics/javafx.concurrent.Service.lambda$executeTask$6(Service.java:725)
        at java.base/java.security.AccessController.doPrivileged(AccessController.java:391)
        at javafx.graphics/javafx.concurrent.Service.lambda$executeTask$7(Service.java:724)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
        at java.base/java.lang.Thread.run(Thread.java:832)
<===========--> 88% EXECUTING [3m 8s]
> :run

5. Try to recover by running:
   ./bitcoin-cli -datadir=signet-custom unloadwallet sparrow

Which also fails to return

6. Kill sparrow process, and restart
7. This time connection establishes but UI continues to show the Unconfirmed parent as well as the following logs from the console

 DEBUG bwt::indexer                      > failed fetching mempool entry for bbe825871e49a284d86f323238415d7d105c9f56a9bb9ed0c1a36606ad1903f8: JSON-RPC error: RPC error response: RpcError { code: -5, message: "Transaction not in mempool", data: None }
2021-03-11 20:18:54,885 ERROR Error in version check address
com.sparrowwallet.drongo.address.InvalidAddressException: Could not parse invalid address 1LiJx1HQ49L2LzhBwbgwXdHiGodvPg5YaV
        at com.sparrowwallet.drongo@0.9/com.sparrowwallet.drongo.address.Address.fromString(Address.java:132)
        at com.sparrowwallet.drongo@0.9/com.sparrowwallet.drongo.address.Address.fromString(Address.java:67)
        at com.sparrowwallet.sparrow@1.2.0/com.sparrowwallet.sparrow.net.VersionCheckService.verifySignature(VersionCheckService.java:68)
        at com.sparrowwallet.sparrow@1.2.0/com.sparrowwallet.sparrow.net.VersionCheckService$1.call(VersionCheckService.java:35)
        at com.sparrowwallet.sparrow@1.2.0/com.sparrowwallet.sparrow.net.VersionCheckService$1.call(VersionCheckService.java:31)
        at javafx.graphics/javafx.concurrent.Task$TaskCallable.call(Task.java:1425)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at javafx.graphics/javafx.concurrent.Service.lambda$executeTask$6(Service.java:725)
        at java.base/java.security.AccessController.doPrivileged(AccessController.java:391)
        at javafx.graphics/javafx.concurrent.Service.lambda$executeTask$7(Service.java:724)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
        at java.base/java.lang.Thread.run(Thread.java:832)
 DEBUG bitcoincore_rpc                   > JSON-RPC request: getblockhash [1733]

[craigraw]

The InvalidAddressException is unrelated - it's just caused by Sparrow failing to parse a mainnet address with a signet configuration. Fixed in 3e287bf.

If Sparrow is disconnecting on a wallet refresh, then it seems bwt (the library Sparrow is using to connect to the node) is experiencing a terminal error. Are there any logs that might indicate why this happening? bwt's debug logging is included inside Sparrow's logging, so it should be present. The bwt logs look similar to the first line in the log excerpts above.

[7hacker]

I think I know whats happening here. Just to be sure i recreated the last result again, but this time captured the full log which is attached below. Reading the logs top to bottom should ideally reflect the events described below but if i missed something let me know. Also curious if you find something additional too

1. Start sparrow wallet with -n signet -l DEBUG
2. Go to View->refresh wallet
3. The bwt library doesn't perform a connection when the wallet is refreshed, because it hits this error that @shesek mentioned in Issue: sparrow cant connect to signet node running on localhost #67 .

dev.bwt.libbwt.BwtException: JSON-RPC error: RPC error response: RpcError { code: -35, message: "Wallet file verification failed. Refusing to load database. Data file \'/Users/nirmal/code/bitcoin/src/signet-custom/signet/wallets/sparrow/wallet.dat\' is already loaded.", data: None }

4. To get around this, I perform the workaround referenced above which is to unload the sparrow wallet
5. Then as mentioned above in point 5 this fails to return, but actually it does return after a very long time. This time i waited :)
6. And finally when it does return, sparrow shows the lost transaction as previously , an 'Unconfirmed Parent'
7. This time i examine the transaction by clicking the magnifying button and the RPC mempool failure is also logged in sparrow.log

Sparrow.log
sparrow.log

[7hacker]

@craigraw

Its possible that this issue concerns a case that is rare/improbable? As you mentioned previously, that broadcasted transactions are not considered 'lost' . However I am puzzled of why the entry switched from "Unconfirmed" to "Unconfirmed Parent". Should it continue staying "Unconfirmed"?

[craigraw]

I believe your thinking is correct - this is a rare/improbable use case, but nevertheless I have been suspicious for some time that there is a subtle bug causing the "Unconfirmed Parent" situation when it is not always correct. That bug might be in bwt however - note that in the Electrum server protocol specification for blockchain.scripthash.get_mempool, the server notifies the client by returning -1 when some of the inputs of a mempool transaction are unconfirmed. Sparrow uses this information to add the "Unconfirmed Parent" label.

Although it should be present in the bwt logging too, may I suggest adding debug logging to SubscriptionService to see how bwt is following the protocol on this - strictly, it should notify the script hashes attached to the transaction to return them to their original states (prior to initiating the test). I should note that Sparrow does not handle that situation as you would expect - a bug in electrs means that Sparrow needs to ignore old script hash statuses, or be overwhelmed with unnecessary server queries after invalid notifications.

It would also be interesting to know if normal situation where a transaction has an unconfirmed parent are working correctly.

cc'ing @shesek (author of bwt)

[shesek]

bwt should be handling transactions with unconfirmed parents correctly and report them with a height of -1, as of v0.1.4. Confirmation of the parent transactions should result in a status hash change and a notification.

If something still seems off on bwt's side, let me know and I'll look into this. It probably wouldn't hurt to add some tests around this at least.

Edit: It's not strictly related, but maybe also worth noting that bwt reports the effective feerate of transactions with unconfirmed parents, calculated as MIN(own_fee/own_vsize, (own_fee+ancestor_fee)/(own_vsize+ancestor_vsize)). It is the only Electrum server implementation that does it, which may result in some different/unexpected behaviors.

[7hacker]

hi @craigraw @shesek thanks for the discussion, here's what I'll do as next steps: check the wallet behavior for an actual unconfirmed parent.

Meanwhile if there's a patch you'd like me to build with that will provide additional logs for Sparrow or BWT, I'm happy to re-run this flow and provide the data for further debugging

[craigraw]

Great - bwt's debug logging is also turned on when Sparrow's is.

[6102bitcoin]

@7hacker did you find time to perform this test with an unconfirmed parent?

Outstanding Action: Identify whether problem still exists. Identify whether fix can be applied to bwt and if so talk to shesek.
Proposed Priority: Low

[7hacker]

@6102bitcoin no i haven't had a chance to try this but I can spend some time on it. Do you have a suggestion of how to generate an unconfirmed parent? I'm using a custom signet here

[6102bitcoin]

I don't. @craigraw might know how