search

sipa / bitcoin

Bitcoin integration/staging tree
http://www.bitcoin.org
MIT License
88 stars 21 forks source link

wallet / node interaction problem? #73

Closed ghost closed 8 years ago

ghost commented 8 years ago

using 35558ed410374bdc5026f694b4ad92e5ecd5c109, which not the latest but doesn't look like more recent changes would affect this (I can update though)

I often get this:

tnu@segneta:~$ ./bitcoin-cli getwalletinfo
{
  "walletversion": 60000,
  "balance": 14009.66777513,
  "unconfirmed_balance": 0.00000000,
  "immature_balance": 0.00000000,
  "txcount": 315,
  "keypoololdest": 1459373243,
  "keypoolsize": 101,
  "paytxfee": 0.00000000
}
tnu@segneta:~$ ./bitcoin-cli sendtoaddress D9J59cHnRUu3ao7g7s4B66wyPNDd7PtTbb 2016
error code: -4
error message:
Error: The transaction was rejected! This might happen if some of the coins in your wallet were already spent, such as if you used a copy of wallet.dat and coins were spent in the copy but not marked as spent here.

in debug.log:

2016-04-14 06:27:06 keypool reserve 28
2016-04-14 06:27:06 keypool return 28
2016-04-14 06:27:40 keypool reserve 28
2016-04-14 06:27:40 CommitTransaction:
CTransaction(hash=129934a178, ver=1, vin.size=22, vout.size=2, nLockTime=17258)
    CTxIn(COutPoint(17d2e0f2d4, 0), scriptSig=483045022100ddfd18ad48fc, nSequence=4294967294)
    CTxIn(COutPoint(2ffd081ad2, 0), scriptSig=47304402203d3c4e0d5fbf11, nSequence=4294967294)
    CTxIn(COutPoint(b78d2d6859, 0), scriptSig=473044022015a450794b14e2, nSequence=4294967294)
    CTxIn(COutPoint(48ad0d7db3, 0), scriptSig=473044022035bde5f06117aa, nSequence=4294967294)
    CTxIn(COutPoint(caacd8e01d, 0), scriptSig=483045022100e19f30bb395e, nSequence=4294967294)
    CTxIn(COutPoint(d34dd024c0, 0), scriptSig=47304402203ce7d3ec69f8e4, nSequence=4294967294)
    CTxIn(COutPoint(674dfed873, 0), scriptSig=483045022100b75103d39088, nSequence=4294967294)
    CTxIn(COutPoint(067c2312cc, 0), scriptSig=483045022100d157a5d8e6b2, nSequence=4294967294)
    CTxIn(COutPoint(c02c354e95, 0), scriptSig=483045022100858eae085392, nSequence=4294967294)
    CTxIn(COutPoint(a8575e93ee, 0), scriptSig=483045022100db8c04bd6b09, nSequence=4294967294)
    CTxIn(COutPoint(3ec547d2fe, 0), scriptSig=4730440220597e5b23e96256, nSequence=4294967294)
    CTxIn(COutPoint(2ff460b92c, 0), scriptSig=47304402203d01ccf9428cd4, nSequence=4294967294)
    CTxIn(COutPoint(686cbe6565, 0), scriptSig=4730440220615cc84ea2d73e, nSequence=4294967294)
    CTxIn(COutPoint(fc480c96ff, 0), scriptSig=473044022048bcb03a9df592, nSequence=4294967294)
    CTxIn(COutPoint(e85c4fac09, 0), scriptSig=483045022100eef530b223bd, nSequence=4294967294)
    CTxIn(COutPoint(e182645a4d, 0), scriptSig=4830450221009638a28e45b5, nSequence=4294967294)
    CTxIn(COutPoint(ef7850153c, 0), scriptSig=4830450221009a5c70b43fb5, nSequence=4294967294)
    CTxIn(COutPoint(8748e5d810, 0), scriptSig=47304402202eac8df9438618, nSequence=4294967294)
    CTxIn(COutPoint(acafdf772e, 0), scriptSig=47304402202840a4fb291d20, nSequence=4294967294)
    CTxIn(COutPoint(e4cdcd1176, 0), scriptSig=47304402206e0417095fe674, nSequence=4294967294)
    CTxIn(COutPoint(0c18f068f6, 0), scriptSig=47304402206688589954730e, nSequence=4294967294)
    CTxIn(COutPoint(0456f26e28, 0), scriptSig=483045022100da99fed25c6e, nSequence=4294967294)
    CTxOut(nValue=2016.00000000, scriptPubKey=76a9142d931607deea7808fe803588)
    CTxOut(nValue=22.69821136, scriptPubKey=76a914d919429cedbfa77780ca607f)
2016-04-14 06:27:40 keypool keep 28
2016-04-14 06:27:40 AddToWallet 129934a178e659f7f92d937842c20453d8a71ee996c27b73c27ba8f8b1b97d89  new
2016-04-14 06:27:40 CommitTransaction(): Error: Transaction not valid

then a few blocks later, the tx will appear on the network. I'll post a comment to this issue when that happens with the debug log.

There's 2 things: one is there some error where the node doesn't like the tx. Then there's also the problem that if the tx fails, it should disappear; if bitcoin-cli returns an error, that means the coins didn't get sent, so naturally I press up, and press enter again, and it sometimes works. But then I'll send 2X as much as I intended which can result in loss of funds.

This might not be segnet related? I've never used bitcoin-cli on mainnet. Also I don't have 2016 coins on mainnet :)

ghost commented 8 years ago

Happened immediately after the next block was found:

2016-04-14 06:43:19 UpdateTip: new best=000000038b1b4df674e09da30da7d2228e00ec53d68df0b8b96761966425c8f7  height=17259  log2_work=46.98245  tx=106077  date=2016-04-14 06:43:35 progress=1.000000  cache=0.6MiB(226tx)
2016-04-14 06:43:19 CreateNewBlock(): total cost 15440 txs: 26 fees: 130000 sigopscost 426
2016-04-14 06:43:19 Running BitcoinMiner with 27 transactions in block (2399 bytes)
2016-04-14 06:43:43 Relaying wtx 129934a178e659f7f92d937842c20453d8a71ee996c27b73c27ba8f8b1b97d89
2016-04-14 06:43:43 ResendWalletTransactions: rebroadcast 1 unconfirmed transactions
2016-04-14 06:43:44 AddToWallet 129934a178e659f7f92d937842c20453d8a71ee996c27b73c27ba8f8b1b97d89

I'm also CPU mining, which feels like it may be a factor because nobody really does that in real life, so could be an interaction of the cpuminer and the wallet.

sipa commented 8 years ago

This shouldn't happen, we need to investigate this.

ghost commented 8 years ago

I can send my wallet.dat if you want to try to reproduce it. I get this behavior pretty regularly, especially on transactions with lots of inputs. (1 input txs usually work)

NicolasDorier commented 8 years ago

The nLockTime of your transaction is 17258. It was rejected the block before because it was still not valid, on the block 17259, the transaction is valid and got broadcasted.

It seems to be a one off error on nLockTime calculation. Not sure if related to segwit, I'm trying to find the source of it.

That or there was a reorg between the time where the transaction was created and when it was broadcasted.

jl2012 commented 8 years ago

Unless the fee is extremely high, fee sniping will incur loss and no miner would do that. This design may do more harm than good

NicolasDorier commented 8 years ago

mmh I'm wrong. Given this code there is 1 chance on 100 for nLockTime to be equal to the current block which was 17258. The transaction should have been accepted to mempool, as the next block (17259) can include it... This is interesting that this bug fired exactly when nLockTime is equal to the current height.

sipa commented 8 years ago

There is a chance of 90.1% for nLockTime to be equal to the current block, and even then, the mempool should accept it as it uses current+1 to check finality.

ghost commented 8 years ago

Unfortunately, I'm not able to reproduce this bug, though I've been trying for the last day or two. It happened somewhat regularly 2 weeks ago. This leads me to think it may be mining related? There's more mining power now and I can't CPU mine any more so I stopped. At this point all my coinbase txs have been spent.

If someone else is currently CPU mining with bitcoind, maybe try sendtoaddress and see if there are any problems? Or if difficulty drops in a few days I can start mining and see if the problem reappears.

ghost commented 8 years ago

Got it again, this time with more logs. Looks mining related. This probably has nothing to do with segwit, though so maybe this isn't the right place for the issue? Would be useful to reproduce it on testnet3.

d649bbc3626702a09d5e3e295a33fa90cd2781484ccb0b76d0fcf6e28b203f9c has not yet been propagated to the network but may soon, we'll see.

2016-04-19 19:51:11 Received a POST request for / from 127.0.0.1:55773
2016-04-19 19:51:11 ThreadRPCServer method=sendtoaddress
2016-04-19 19:51:11 SelectCoins() best subset: 50.27495 50.04445 50.04445 50.04445 50.04445 50.04445 50.0004992 50.0002048 50.00 50.00 50.00 50.00 50.00 50.00 50.00 50.00 50.00 50.00 50.00 50.00 total 1000.497904
2016-04-19 19:51:11 keypool reserve 17
2016-04-19 19:51:11   2: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  46.37%    9115.6/(19660.1+0 mempool)
2016-04-19 19:51:11   3: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  53.29%   10477.1/(19660.1+0 mempool)
2016-04-19 19:51:11   4: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  58.50%   11500.7/(19660.1+0 mempool)
2016-04-19 19:51:11   5: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  64.58%   12696.2/(19660.1+0 mempool)
2016-04-19 19:51:11   6: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  71.51%   14058.1/(19660.1+0 mempool)
2016-04-19 19:51:11   7: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  78.54%   15441.5/(19660.1+0 mempool)
2016-04-19 19:51:11   8: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  85.29%   16768.4/(19660.1+0 mempool)
2016-04-19 19:51:11   9: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  90.43%   17778.5/(19660.1+0 mempool)
2016-04-19 19:51:11  10: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  92.81%   18246.0/(19660.1+0 mempool)
2016-04-19 19:51:11  11: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  93.21%   18325.7/(19660.1+0 mempool)
2016-04-19 19:51:11  12: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  93.22%   18326.5/(19660.1+0 mempool)
2016-04-19 19:51:11  13: For conf success > 0.95 need FeeRate >:        40983 from buckets  41144.8 -  45259.3  Cur Bucket stats 100.00%      15.2/(15.2+0 mempool)
2016-04-19 19:51:11 SelectCoins() best subset: 50.76091246 50.16190544 50.04445 50.04445 50.04445 50.04445 50.04445 50.0004992 50.0002048 50.00 50.00 50.00 50.00 50.00 50.00 50.00 50.00 50.00 50.00 50.00 total 1001.1457719
2016-04-19 19:51:11   2: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  46.37%    9115.6/(19660.1+0 mempool)
2016-04-19 19:51:11   3: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  53.29%   10477.1/(19660.1+0 mempool)
2016-04-19 19:51:11   4: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  58.50%   11500.7/(19660.1+0 mempool)
2016-04-19 19:51:11   5: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  64.58%   12696.2/(19660.1+0 mempool)
2016-04-19 19:51:11   6: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  71.51%   14058.1/(19660.1+0 mempool)
2016-04-19 19:51:11   7: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  78.54%   15441.5/(19660.1+0 mempool)
2016-04-19 19:51:11   8: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  85.29%   16768.4/(19660.1+0 mempool)
2016-04-19 19:51:11   9: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  90.43%   17778.5/(19660.1+0 mempool)
2016-04-19 19:51:11  10: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  92.81%   18246.0/(19660.1+0 mempool)
2016-04-19 19:51:11  11: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  93.21%   18325.7/(19660.1+0 mempool)
2016-04-19 19:51:11  12: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  93.22%   18326.5/(19660.1+0 mempool)
2016-04-19 19:51:11  13: For conf success > 0.95 need FeeRate >:        40983 from buckets  41144.8 -  45259.3  Cur Bucket stats 100.00%      15.2/(15.2+0 mempool)
2016-04-19 19:51:11 SelectCoins() best subset: 50.27495 50.16190544 50.04445 50.04445 50.04445 50.04445 50.0004992 50.0002048 50.00 50.00 50.00 50.00 50.00 50.00 50.00 50.00 50.00 50.00 50.00 50.00 total 1000.61535944
2016-04-19 19:51:11   2: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  46.37%    9115.6/(19660.1+0 mempool)
2016-04-19 19:51:11   3: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  53.29%   10477.1/(19660.1+0 mempool)
2016-04-19 19:51:11   4: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  58.50%   11500.7/(19660.1+0 mempool)
2016-04-19 19:51:11   5: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  64.58%   12696.2/(19660.1+0 mempool)
2016-04-19 19:51:11   6: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  71.51%   14058.1/(19660.1+0 mempool)
2016-04-19 19:51:11   7: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  78.54%   15441.5/(19660.1+0 mempool)
2016-04-19 19:51:11   8: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  85.29%   16768.4/(19660.1+0 mempool)
2016-04-19 19:51:11   9: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  90.43%   17778.5/(19660.1+0 mempool)
2016-04-19 19:51:11  10: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  92.81%   18246.0/(19660.1+0 mempool)
2016-04-19 19:51:11  11: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  93.21%   18325.7/(19660.1+0 mempool)
2016-04-19 19:51:11  12: For conf success > 0.95 need FeeRate >:           -1 from buckets  2.1e+15 -  2.1e+15  Cur Bucket stats  93.22%   18326.5/(19660.1+0 mempool)
2016-04-19 19:51:11  13: For conf success > 0.95 need FeeRate >:        40983 from buckets  41144.8 -  45259.3  Cur Bucket stats 100.00%      15.2/(15.2+0 mempool)
2016-04-19 19:51:11 CommitTransaction:
2016-04-19 19:51:11 received: getdata (37 bytes) peer=20
2016-04-19 19:51:11 received getdata (1 invsz) peer=20
2016-04-19 19:51:11 received getdata for: tx 04d3e378d6ee04a4b3ad90194deb0da62b8f4d7d2a8b19567b45b56e070f06e4 peer=20
2016-04-19 19:51:11 keypool keep 17
2016-04-19 19:51:11 AddToWallet d649bbc3626702a09d5e3e295a33fa90cd2781484ccb0b76d0fcf6e28b203f9c  new
2016-04-19 19:51:11 CommitTransaction(): Error: Transaction not valid
ghost commented 8 years ago

It was broadcast, but not after a block came out. Nothing seems to have prompted the broadcast.

2016-04-19 20:11:19 sending: pong (8 bytes) peer=113
2016-04-19 20:11:20 sending: ping (8 bytes) peer=113
2016-04-19 20:11:20 received: pong (8 bytes) peer=113
2016-04-19 20:11:43 sending: ping (8 bytes) peer=22
2016-04-19 20:11:43 sending: ping (8 bytes) peer=29
2016-04-19 20:11:43 sending: ping (8 bytes) peer=38
2016-04-19 20:11:43 sending: ping (8 bytes) peer=61
2016-04-19 20:11:44 received: pong (8 bytes) peer=29
2016-04-19 20:11:44 received: pong (8 bytes) peer=22
2016-04-19 20:11:44 received: ping (8 bytes) peer=22
2016-04-19 20:11:44 sending: pong (8 bytes) peer=22
2016-04-19 20:11:44 received: pong (8 bytes) peer=38
2016-04-19 20:11:44 received: pong (8 bytes) peer=61
2016-04-19 20:11:44 received: ping (8 bytes) peer=61
2016-04-19 20:11:44 sending: pong (8 bytes) peer=61
2016-04-19 20:11:45 received: ping (8 bytes) peer=97
2016-04-19 20:11:45 sending: pong (8 bytes) peer=97
2016-04-19 20:11:45 sending: ping (8 bytes) peer=97
2016-04-19 20:11:46 received: pong (8 bytes) peer=97
2016-04-19 20:11:48 received: ping (8 bytes) peer=38
2016-04-19 20:11:48 sending: pong (8 bytes) peer=38
2016-04-19 20:11:52 Relaying wtx d649bbc3626702a09d5e3e295a33fa90cd2781484ccb0b76d0fcf6e28b203f9c
2016-04-19 20:11:52 Relaying wtx 9a75ca274ef5d8d700bd1cca1fcffca16b0e44033e5c43518a6b7bd3ebbe3939
2016-04-19 20:11:52 ResendWalletTransactions: rebroadcast 2 unconfirmed transactions
2016-04-19 20:11:52 sending: inv (73 bytes) peer=110
2016-04-19 20:11:52 received: getdata (73 bytes) peer=110
2016-04-19 20:11:52 received getdata (2 invsz) peer=110
2016-04-19 20:11:52 received getdata for: tx d649bbc3626702a09d5e3e295a33fa90cd2781484ccb0b76d0fcf6e28b203f9c peer=110
2016-04-19 20:11:52 sending: tx (2348 bytes) peer=110
2016-04-19 20:11:52 sending: tx (758 bytes) peer=110
2016-04-19 20:11:52 sending: inv (73 bytes) peer=20
2016-04-19 20:11:52 received: getdata (37 bytes) peer=20
2016-04-19 20:11:52 received getdata (1 invsz) peer=20
2016-04-19 20:11:52 received getdata for: tx d649bbc3626702a09d5e3e295a33fa90cd2781484ccb0b76d0fcf6e28b203f9c peer=20
2016-04-19 20:11:52 sending: tx (2348 bytes) peer=20
2016-04-19 20:11:52 sending: inv (73 bytes) peer=22
2016-04-19 20:11:52 sending: inv (73 bytes) peer=113
2016-04-19 20:11:52 received: inv (37 bytes) peer=18
2016-04-19 20:11:52 got inv: tx 9a75ca274ef5d8d700bd1cca1fcffca16b0e44033e5c43518a6b7bd3ebbe3939  new peer=18
2016-04-19 20:11:52 askfor tx 9a75ca274ef5d8d700bd1cca1fcffca16b0e44033e5c43518a6b7bd3ebbe3939  0 (00:00:00) peer=18
2016-04-19 20:11:52 Requesting tx 9a75ca274ef5d8d700bd1cca1fcffca16b0e44033e5c43518a6b7bd3ebbe3939 peer=18
2016-04-19 20:11:52 sending: getdata (37 bytes) peer=18
2016-04-19 20:11:52 received: tx (758 bytes) peer=18
2016-04-19 20:11:52 Blockpolicy mempool tx 9a75ca274e not adding
2016-04-19 20:11:52 AddToWallet 9a75ca274ef5d8d700bd1cca1fcffca16b0e44033e5c43518a6b7bd3ebbe3939  
2016-04-19 20:11:52 AcceptToMemoryPool: peer=18: accepted 9a75ca274ef5d8d700bd1cca1fcffca16b0e44033e5c43518a6b7bd3ebbe3939 (poolsz 17197 txn, 13774 kB)
2016-04-19 20:11:52 received: getdata (37 bytes) peer=113
2016-04-19 20:11:52 received getdata (1 invsz) peer=113
2016-04-19 20:11:52 received getdata for: tx d649bbc3626702a09d5e3e295a33fa90cd2781484ccb0b76d0fcf6e28b203f9c peer=113
2016-04-19 20:11:52 CreateNewBlock(): total cost 3995680 txs: 9072 fees: 45360000 sigopscost 9472
2016-04-19 20:11:52     - Sanity checks: 1.96ms [4.60s]
2016-04-19 20:11:53     - Fork checks: 21.31ms [11.21s]
2016-04-19 20:11:53       - Connect 9073 transactions: 136.79ms (0.015ms/tx, 0.015ms/txin) [463.51s]
2016-04-19 20:11:53     - Verify 9072 txins: 136.90ms (0.015ms/txin) [1620.59s]
2016-04-19 20:11:53 Running BitcoinMiner with 9073 transactions in block (744173 bytes)
2016-04-19 20:11:53 CreateNewBlock(): total cost 3995680 txs: 9072 fees: 45360000 sigopscost 9472
2016-04-19 20:11:53     - Sanity checks: 2.01ms [4.60s]
2016-04-19 20:11:53     - Fork checks: 21.21ms [11.24s]
NicolasDorier commented 8 years ago

Thanks a lot, I'll try to reproduce it today with a fresh node same height with same transaction.

NicolasDorier commented 8 years ago

@T909 I created a new node and tried to reproduce your problem with the first transaction. I synced to 17258 and broadcased 129934a178e659f7f92d937842c20453d8a71ee996c27b73c27ba8f8b1b97d89 expecting it would be rejected. Sadly, it was not rejected. so I could not reproduce. I'm not sure how I can do. :(

NicolasDorier commented 8 years ago

@T909 sipa made this commit to get more info about the reason of rejection https://github.com/sipa/bitcoin/commit/7accc969195eaa5932d50101f767996ee94a05cf can you try ?

sipa commented 8 years ago

I believe this was solved?

ghost commented 8 years ago

I haven't seen the problem again with more recent builds, but not sure what changed to fix it. I can close this I guess. I'm a little worried there may still be an issue, but seeing as nobody mines with setgetnerate=1 there's likely minimal risk.