rpc: sendrawtransaction fails with "[MainThread ] [DEBUG] error pushing = -25 Missing inputs"

[HamishMacEwan]

The command:

python sendpayment.py -m 1 wallet.jmdat XXXXXX 3xxxxx

All seemed to be going fine, then the sendrawtransaction failed and sendpayment.py repeatedly attempted the same process:

2020-02-02 15:05:56,302 [MainThread  ] [INFO ]  all makers have sent their signatures
2020-02-02 15:05:56,303 [MainThread  ] [INFO ]  INFO:Transaction is valid, signing..
2020-02-02 15:05:56,304 [MainThread  ] [DEBUG]  schedule item was:

2020-02-02 15:05:56,322 [MainThread  ] [INFO ]  txid = 6e78ce55fa1c6fb872add876b0f69cb789c5ed0f6b5ca854b2dbf08197b166f8
2020-02-02 15:05:56,328 [MainThread  ] [DEBUG]  rpc: sendrawtransaction ['010000000001095006989f7aecefd1d168b55309ace3a602fce...truncated']

2020-02-02 15:05:56,535 [MainThread  ] [DEBUG]  error pushing = -25 Missing inputs
2020-02-02 15:05:56,535 [MainThread  ] [INFO ]  Retrying with: 8 counterparties

It's joinmarket-clientserver 0.6.1 with Bitcoin Core v0.19.0.1 and it has run yg-privacyenhanced.py successfully. This was my first sendpayment in a new environment, myNodeBTC.com

[HamishMacEwan]

I tried pushing a transaction through other services by hand and it does appear that there were problems with an input (but weren't they checked before accepting?)

53278d78ed4ae2c60ba0ba264d2b0f86285bdb2c7a305e7ac5c4648f5bc03d19 referenced by input 7 of 416dd4f9278ed966663891bdda941650b00b3035878969d189c987877deefb49 has already been spent.

[HamishMacEwan]

The disappointing result is that sendpayment.py then ignores the failure, doesn't attribute it to the defecting peer and repeats with the same respondents...

[AdamISZ]

Inputs can become invalid during the process, if they get consumed in another transaction. And this certainly needn't be malicious, since ygs are designed to handle requests concurrently; they cannot lock/hold utxos they offer in CJ tx 1 before negotiating CJ tx2, because that opens a DOS vector (just lock all their utxos and don't broadcast).

Re: 'disappointing result': the idea is that the script will try again to create a tx if it fails initially, whatever the reason. So that part shouldn't be disappointing, but 'trying with the same peers' is arguably not ideal (although as per above, maliciousness cannot be assumed).

[HamishMacEwan]

With respect to the maliciousness. I would have thought the window for inadvertent presentation of a UTXO, subsequently re-spent and compromising an earlier offer would be extremely narrow, and the joinmarket client would track what it had offered and until seeing the TX or timeout, not offer it in another TX. This has happened to me twice (and a few successful payments in between).

[AdamISZ]

(Will try to respond again shortly, but one detail, could you record your JM version?)

[HamishMacEwan]

Hi,

According to the release notes directory, 0.6.1.

However I have since discovered that the source of the error pushing = -25 Missing inputs is my own wallet, one we have met before in another thread.

This was discovered using sendpayment.py -N 0 -m 2 wallet.jmdat 0 bc1....

Which failed with the Missing inputs error. The more verbose and helpful https://live.blockcypher.com/btc/pushtx/ gave me "Error validating transaction: Transaction 4c454db766868863daa50f34de324c526fea9c52706de7bcadaa6091d794430a referenced by input 0 of 5fe7e4aad69edf3e39be6e80dfe0d53e6c44cc55f28f3717fef230b9ef232f54 has already been spent.."

I have run python wallet-tools.py recover on it a number of times, each giving a different total balance from wallet-tools.py summary. The balance was exciting, but obviously wrong and the results of the sweeping attempted above confirmed that.

[AdamISZ]

Thanks re: version (you can do git log if you installed via git clone and ). I have not much apart from general guesses as to what would cause such apparently wildly incorrect behaviour.

Have you used the --recoversync flag when doing wallet-tool.py? This was something that changed a couple of months back, the default is now what we used to call 'fast', which doesn't work when you move to a new node.

E.g. see this note in the bugfix that 0.6.1 was for:

"This situation can be rectified in two steps: (1) do python wallet-tool.py --recoversync walletname.jmdat; this step does the necessary imports (a reminder, the default sync is now the "fast" version as of 0.6.0 and this is still true in the new release), and then doing a bitcoin-cli rescanblockchain X where X is the blockheight, choosing X definitely before the deposit transaction (a reminder: rescanblockchain is just faster than ordinary rescan, which takes a very long time since it rescans from the genesis block)."

(it was referring to a specific bug that probably didn't affect you, but these instructions might help).

[HamishMacEwan]

According to Trezor, where I restored the 12 words to confirm the UTXOs, and have subsequently spent from successfully, the balance over the five mix levels is 0.30632695 BTC

I've used the --recoversync flag as shown below:

$ python wallet-tool.py -v 3 --recoversync JimmySegwit.jmdat summary

Balance for mixdepth 0: 0.04257319
Balance for mixdepth 1: 4.77200969
Balance for mixdepth 2: 3.10988454
Balance for mixdepth 3: 0.00000000
Balance for mixdepth 4: 0.00000000
Total balance:  7.92446742

Exciting, but completely wrong.

I restored the 12 word seed again and got this result.

$ python wallet-tool.py -v 3 --recoversync js20200215.jmdat summary

Balance for mixdepth 0: 0.04257319
Balance for mixdepth 1: 4.17186293
Balance for mixdepth 2: 2.28368854
Balance for mixdepth 3: 0.00000000
Balance for mixdepth 4: 0.00000000
Total balance:  6.49812466

Less exciting, completely wrong, and inconsistent with the previous restoration of the wallet seed.

In case it helps, this is running on a myNodeBTC.com instance on a Raspberry Pi 4B. Bitcoin Core version v0.19.0.1 and lnd 0.9.0

$ bitcoin-cli listlabels
[
  "bc1[redacted]",
  "bc1[redacted]",
  "bc1[redacted]",
  "bc1[redacted]",
  "joinmarket-wallet-5ae6c7",
  "joinmarket-wallet-d6fef8"
]

Attached the full output of the wallet-tool.py runs above: js20200215.txt JimmySegwit.txt

[AdamISZ]

Thanks for the extra info.

Are you sure the bitcoin node is up to date? I mean it seems like a silly question, but at least it would explain the symptoms. (also: is it pruned?).

I haven't seen reports of this kind of behaviour; can only guess. If anyone else could chip in with ideas it'd be appreciated. Unless I have something to reproduce this is the best I can do.

I'll also double check that there is nothing weird about the summary method that could conceivably cause incorrect results, but I very much doubt it.

(btw -v does nothing here, it's only for the history method)

[HamishMacEwan]

Up to date, not pruned. Thanks for the tip about v. And thank you for your continuing interest in this seemingly intractable problem. I ran bitcoin-cli rescanblockchain 544274 (based on the creation date of the wallet) but no improvement in summary balance.

scripts $ bitcoin-cli getblockchaininfo
{
  "chain": "main",
  "blocks": 617819,
  "headers": 617819,
  "bestblockhash": "000000000000000000119eb9dc0b887c9285d8555b35e74cb13b60fcd3ccf482",
  "difficulty": 15546745765529.37,
  "mediantime": 1581960927,
  "verificationprogress": 0.9999998201019724,
  "initialblockdownload": false,
  "chainwork": "00000000000000000000000000000000000000000cc723c1fa93b1a56d8b5a80",
  "size_on_disk": 299010315707,
  "pruned": false,
  "softforks": {
    "bip34": {
      "type": "buried",
      "active": true,
      "height": 227931
    },
    "bip66": {
      "type": "buried",
      "active": true,
      "height": 363725
    },
    "bip65": {
      "type": "buried",
      "active": true,
      "height": 388381
    },
    "csv": {
      "type": "buried",
      "active": true,
      "height": 419328
    },
    "segwit": {
      "type": "buried",
      "active": true,
      "height": 481824
    }
  },
  "warnings": ""
}

[AdamISZ]

OK, just to summarize/clarify overall situation:

On full (not pruned) and synced Core instance, you have a now persistent (but earlier fluctuated) reporting of a balance, which is significantly larger than real, and which, I take it, represents coins that were in the wallet, but no longer (connecting back to the start of the thread - wallet tries to spend already-spent coins).

(Just in case (a) I got anything wrong or (b) someone else finds it useful).

By the way I went back and re-read your earlier comment to see if I'd missed anything. Did I read it correctly that you entered the same recovery seed twice, for the two *.jmdat files? Because I notice that you have two joinmarket-wallet-* labels. Maybe it's nothing but just thought I'd mention.

What's strange about this problem is not a failure to sync fully; that has happened plenty of times, in recovery on new Core instances, and it's mostly a case of inconvenient rescanning (sometimes more than once, because of not knowing hd index info). But this case is different - you are over-recording the balance; which would be less strange if we built the wallet's state by replaying transactions (and just missed some!), but we don't! We use listunspent to find all the utxos and then check two things on each of them: (a) are they known to the wallet (b) do they have the correct wallet label (deterministically generated from the first address in the wallet). I can't make sense of it; it doesn't look (superficially) like double counting, as you have way more than the real amount.

[HamishMacEwan]

Did I read it correctly that you entered the same recovery seed twice, for the two *.jmdat files?

Yes. JimmySegwit.jmdat and js20200215.jmdat were separate recoveries using the same seed words and password.

Because I notice that you have two joinmarket-wallet-* labels.

The second label is for a wallet I created sui generis on the myNodeBTC instance. Thus joinmarket-wallet-d6fef8 is the label for both files mentioned above.

The Bitcoin Core instance has never been used directly, its wallet has no transactions or balance. It simply maintains the blockchain, mempool and indexes used by lnd and electrs.

I have spent from the wallet seed, after restoring it on a Trezor 1, and will now sweep it. If you wish, I can provide you with the wallet seed, password and any other files considered useful once this is done. You might be able to find out more with hands on access and without any fumbling I might be introducing in these reports.

[fiatjaf]

I'm seeing this same behavior: restored from a seed, used an up-to-date bitcoind to rescan, and I'm getting spent UTXOs listed in my JoinMarket wallet.

[fiatjaf]

From a quick glance it looks like all change UTXOs are spent while the non-change ones are OK.

[HamishMacEwan]

I've also had recent experience with this when I lost a node a couple of months back and had to rebuild it from near scratch. I haven't raised the matter, as it occurred in difficult circumstances to debug, to whit the JoininBox component of myNodeBTC.

[AdamISZ]

@fiatjaf just to be clear, in the case where you are seeing spent utxos reported as unspent, do those utxos, that you know are actually spent txos, show up in the output of python wallet-tool.py wallet.jmdat showutxos?

Also any more details about your case might help to give a clue, as the intersection of your case with @HamishMacEwan 's might tell us something.

I'm thinking about it now, again; I'm still trying to figure out how we could be getting listunspent to show txos that are actually spent (which is the symptom both of you seemed to describe).

[fiatjaf]

The only thing I tried (besides a normal spend) was to use python wallet-tool.py wallet.jmdat display and it showed addresses with balances they didn't actually have. Let me try showutxos.

Also another thing that may have not been clear is that these spent txos were not spent to elsewhere, they were spent to the same JM wallet, thus the new UTXOs that should be showing up in the wallet are not.

[fiatjaf]

Yes, they do show up in showutxos.

[fiatjaf]

Couldn't it be that the blockchain rescan broke at some point? I've called it with

bitcoin-cli -rpcwallet=jm_wallet rescanblockchain 500000

[AdamISZ]

@fiatjaf so would a reasonable attempt to reproduce be something like:

• make a wallet, fund
• send two or three txs from mixdepth 0 to mixdepth 1 (say)
• shut down, move to a new Core instance
• once synced, recover same JM wallet from seed
• do rescanblockchain

?

(Not sure how I'll do this on regtest due to the 'new Core instance' part (on same regtest blockchain), but doubtless I can figure it out).

[fiatjaf]

Yes, that sounds right.

Instead of a new Core instance I think you can just delete the JM core wallet, no? I think that will work.

[AdamISZ]

I think I've figured out a plausible explanation for this bug. It fits, in particular in that this might not be repeatable, and only seen occasionally. The logic is as follows:

This describes the situation for a run of python wallet-tool.py wallet.jmdat display (or summary, same):

On startup, we read the current *.jmdat wallet file, which contains the set of utxos in the wallet as it was last seen. We do that here:

https://github.com/JoinMarket-Org/joinmarket-clientserver/blob/fea33cbb6f3b4337a7267d4a2b807ab1af718026/jmclient/jmclient/wallet.py#L359

Then, having loaded and created a *Wallet object with its associated Storage object, we proceed to the syncing stage, at the end of this code block:

https://github.com/JoinMarket-Org/joinmarket-clientserver/blob/fea33cbb6f3b4337a7267d4a2b807ab1af718026/jmclient/jmclient/wallet_utils.py#L1630-L1647

Now, note here that the code path diverges based on whether you've chosen fast sync (default) or detailed/recovery sync, but for the purposes of this, we end up in the same place. Whichever you choose, you set the WalletService.synced flag based on the outcome of WalletService.sync_addresses or WalletService.sync_addresses_fast, and after calling one of those two, you call WalletService.sync_unspent, and this is (I believe) where we find the culprit:

https://github.com/JoinMarket-Org/joinmarket-clientserver/blob/fea33cbb6f3b4337a7267d4a2b807ab1af718026/jmclient/jmclient/wallet_service.py#L806-L815

As you can see from the opening section of the function, the call to *Wallet.reset_utxos() only occurs if the attempt to read the block height succeeds. If it does not, nothing happens, and that's the problem. The utxo set in the wallet file is not erased, so the earlier one is still left intact. But the synced flag for the wallet has already been set to True, even though that isn't actually right.

(Note that jmclient.BitcoinCoreInterface.get_current_blockheight swallows RPC errors and just returns None on failure).

[AdamISZ]

Yes, that sounds right.

Instead of a new Core instance I think you can just delete the JM core wallet, no? I think that will work.

Yeah i was mulling that over. I'm just not sure the addresses get 'unimported' fully from that.

Anyway I think I found the bug as per above. Tricky to prove it's correct but if you force jmclient.BitcoinCoreInterface.get_current_block_height to fail, it should give the same result.

[AdamISZ]

A point that can cause confusion with anyone testing this:

When you run the wallet-tool script, you are opening the Storage object (that manages the contents of the *jmdat file) in read-only mode; that means that you will not update the contents of the file, whatever happens. However as per above, when things are working correctly, you are resetting the actual in-memory utxo database on startup, so it will change the contents of the utxo set during the working of the program. It just won't commit that change to disk.

So if you are testing out this scenario, that will explain this behaviour: if you have an out of date utxo set in the jmdat file, and you run wallet-tool and force the RPC call to get the block height to fail, you will see the out of date utxo set displayed. If you then try again, the same thing will keep happening, as long as you are only running wallet-tool, and not other scripts/apps that open the Storage for writing, and actually overwrite the contents.