Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

mempool transactions disappear if hundreds of blocks suddenly get mined #630

Closed
SomberNight opened this issue Nov 1, 2018 · 10 comments

Comments

@SomberNight
Copy link
Contributor

commented Nov 1, 2018

On 214fc83, bitcoin core 0.17.

On regtest,

  • user broadcasts a transaction
  • tx gets into mempool; both bitcoind and electrumx see it
  • mine 1000 blocks with bitcoind
  • blockchain.scripthash.* methods will NOT include the tx, it's as if it never existed
  • restarting electrumx fixes the issue

Ran into this bug during integration tests, and as a bug in bitcoind or electrumx was the last thing we considered, this cost us many hours :/

// tx 55937a61e1bfb598213a0cd3faa61f9a578d03ef334fd30e686c3d47d002c734 broadcasted, already in mempool
$ printf '{"id": 1, "method": "server.version", "params": ["testing", "1.4"]}\n{"id": 2, "method": "blockchain.scripthash.subscribe", "params": ["8c0e387c4224cd0c5c624b83a36fd59a54d8c301887302081447819a26281435"]}\n' | nc 127.0.0.1 50001
{"jsonrpc": "2.0", "result": ["ElectrumX 1.8.8", "1.4"], "id": 1}
{"jsonrpc": "2.0", "result": "e57ed8cb645e801f89266d58b1bbc44acf25f9861248ff3c94ed00d8944d09c4", "id": 2}
^C
$ printf '{"id": 1, "method": "server.version", "params": ["testing", "1.4"]}\n{"id": 2, "method": "blockchain.scripthash.get_history", "params": ["8c0e387c4224cd0c5c624b83a36fd59a54d8c301887302081447819a26281435"]}\n' | nc 127.0.0.1 50001
{"jsonrpc": "2.0", "result": ["ElectrumX 1.8.8", "1.4"], "id": 1}
{"jsonrpc": "2.0", "result": [{"tx_hash": "55937a61e1bfb598213a0cd3faa61f9a578d03ef334fd30e686c3d47d002c734", "height": 0, "fee": 141}], "id": 2}
^C
$ printf '{"id": 1, "method": "server.version", "params": ["testing", "1.4"]}\n{"id": 2, "method": "blockchain.transaction.get", "params": ["55937a61e1bfb598213a0cd3faa61f9a578d03ef334fd30e686c3d47d002c734"]}\n' | nc 127.0.0.1 50001
{"jsonrpc": "2.0", "result": ["ElectrumX 1.8.8", "1.4"], "id": 1}
{"jsonrpc": "2.0", "result": "010000000001010ea8bda0f5939cf28359a551835afb27de092ecb441e782afdaef19c9059d78c0100000000fdffffff02706408000000000016001470ea2d19cfdc1ff2a25a126486dcdc81a0511160df739f02000000001600140f54f30dd40bd63b02d9d0d888ff8c00fee745de0248304502210090af9baf1705c5f711e317dfeab00815a9a773c15c98338ea088db6e16a5090202201eaa61e7af2d3de296f1cc4b0cd4dd30e7a5d069eeee778be55eece55bb9a9b0012102802ac4c8a3bfc0d95207b830514bb78e4c3676b481e1eec259792b2d80d8ee0dc8110000", "id": 2}
^C
$ printf '{"id": 1, "method": "server.version", "params": ["testing", "1.4"]}\n{"id": 2, "method": "blockchain.headers.subscribe"}\n' | nc 127.0.0.1 50001
{"jsonrpc": "2.0", "result": ["ElectrumX 1.8.8", "1.4"], "id": 1}
{"jsonrpc": "2.0", "result": {"hex": "00000020b1e4a0792fc5c9afacc7c5d8480a7a5057dff658941859495ef87c64cc8abf376d33283ce6732baa6c5c2f0dcb09ac8f74f3698ec5b707b22bc49d780af06eb19320db5bffff7f2001000000", "height": 4552}, "id": 2}



// mine loads of blocks suddenly

$ bitcoin-cli -rpcuser=btc_rpc_user -rpcpassword=asdasd -rpcport=18332 -regtest generate 1000
...

// tx 55937a61e1bfb598213a0cd3faa61f9a578d03ef334fd30e686c3d47d002c734 is mined in block 4553

$ bitcoin-cli -rpcuser=btc_rpc_user -rpcpassword=asdasd -rpcport=18332 -regtest getblock $(bitcoin-cli -rpcuser=btc_rpc_user -rpcpassword=asdasd -rpcport=18332 -regtest getblockhash 4553)
{
  "hash": "62a42e8414ffddc7090ce34ea28da662f6c92b1a6c6da43a4b7f19276cbb37a7",
  "confirmations": 1000,
  "strippedsize": 341,
  "size": 487,
  "weight": 1510,
  "height": 4553,
  "version": 536870912,
  "versionHex": "20000000",
  "merkleroot": "5f0d96ad8291d3393c0c11197574fdbeab0680b34f325d4b4e975c3dfdbbc8b3",
  "tx": [
    "e1608f4fa1db799213efbbfcc35762b18b4c152a7d3e7553c4756e8283f870eb",
    "55937a61e1bfb598213a0cd3faa61f9a578d03ef334fd30e686c3d47d002c734"
  ],
  "time": 1541088386,
  "mediantime": 1541087378,
  "nonce": 1,
  "bits": "207fffff",
  "difficulty": 4.656542373906925e-10,
  "chainwork": "0000000000000000000000000000000000000000000000000000000000002394",
  "nTx": 2,
  "previousblockhash": "608ba798d16da8cc72a47e342828ec37fd20b325bc9088ad1904bcc7fad4f651",
  "nextblockhash": "056fb8d95b2db3ada46da2d362bb2cb2c05ad00c6a16abf959004bcc69eb24c9"
}


// electrumx does not know about tx 55937a61e1bfb598213a0cd3faa61f9a578d03ef334fd30e686c3d47d002c734  at all !

$ printf '{"id": 1, "method": "server.version", "params": ["testing", "1.4"]}\n{"id": 2, "method": "blockchain.scripthash.subscribe", "params": ["8c0e387c4224cd0c5c624b83a36fd59a54d8c301887302081447819a26281435"]}\n' | nc 127.0.0.1 50001
{"jsonrpc": "2.0", "result": ["ElectrumX 1.8.8", "1.4"], "id": 1}
{"jsonrpc": "2.0", "result": null, "id": 2}
^C
$ printf '{"id": 1, "method": "server.version", "params": ["testing", "1.4"]}\n{"id": 2, "method": "blockchain.scripthash.get_history", "params": ["8c0e387c4224cd0c5c624b83a36fd59a54d8c301887302081447819a26281435"]}\n' | nc 127.0.0.1 50001
{"jsonrpc": "2.0", "result": ["ElectrumX 1.8.8", "1.4"], "id": 1}
{"jsonrpc": "2.0", "result": [], "id": 2}
^C
$ printf '{"id": 1, "method": "server.version", "params": ["testing", "1.4"]}\n{"id": 2, "method": "blockchain.transaction.get", "params": ["55937a61e1bfb598213a0cd3faa61f9a578d03ef334fd30e686c3d47d002c734"]}\n' | nc 127.0.0.1 50001
{"jsonrpc": "2.0", "result": ["ElectrumX 1.8.8", "1.4"], "id": 1}
{"jsonrpc": "2.0", "result": "010000000001010ea8bda0f5939cf28359a551835afb27de092ecb441e782afdaef19c9059d78c0100000000fdffffff02706408000000000016001470ea2d19cfdc1ff2a25a126486dcdc81a0511160df739f02000000001600140f54f30dd40bd63b02d9d0d888ff8c00fee745de0248304502210090af9baf1705c5f711e317dfeab00815a9a773c15c98338ea088db6e16a5090202201eaa61e7af2d3de296f1cc4b0cd4dd30e7a5d069eeee778be55eece55bb9a9b0012102802ac4c8a3bfc0d95207b830514bb78e4c3676b481e1eec259792b2d80d8ee0dc8110000", "id": 2}
^C
$ printf '{"id": 1, "method": "server.version", "params": ["testing", "1.4"]}\n{"id": 2, "method": "blockchain.headers.subscribe"}\n' | nc 127.0.0.1 50001
{"jsonrpc": "2.0", "result": ["ElectrumX 1.8.8", "1.4"], "id": 1}
{"jsonrpc": "2.0", "result": {"hex": "0000002076dbfb0f1dfe05af52a14a48698e64a29df28b44a6262bbb8537ffec9617695383982ec1426782575e95ff96d2f0f1f0f7e1aada4383b5a9303b90c8d41024902825db5bffff7f2002000000", "height": 5552}, "id": 2}
^C



// restart electrumX
// now electrum knows about the tx

$ printf '{"id": 1, "method": "server.version", "params": ["testing", "1.4"]}\n{"id": 2, "method": "blockchain.scripthash.subscribe", "params": ["8c0e387c4224cd0c5c624b83a36fd59a54d8c301887302081447819a26281435"]}\n' | nc 127.0.0.1 50001
{"jsonrpc": "2.0", "result": ["ElectrumX 1.8.8", "1.4"], "id": 1}
{"jsonrpc": "2.0", "result": "1a39eedf100a0e38fe39055a0ce25186bc1f759b30c458b7cbea13568897bb2a", "id": 2}
^C
$ printf '{"id": 1, "method": "server.version", "params": ["testing", "1.4"]}\n{"id": 2, "method": "blockchain.scripthash.get_history", "params": ["8c0e387c4224cd0c5c624b83a36fd59a54d8c301887302081447819a26281435"]}\n' | nc 127.0.0.1 50001
{"jsonrpc": "2.0", "result": ["ElectrumX 1.8.8", "1.4"], "id": 1}
{"jsonrpc": "2.0", "result": [{"tx_hash": "55937a61e1bfb598213a0cd3faa61f9a578d03ef334fd30e686c3d47d002c734", "height": 4553}], "id": 2}
^C
@SomberNight

This comment has been minimized.

Copy link
Contributor Author

commented Nov 1, 2018

If I mine 300 blocks, whether I can reproduce is probabilistic. Sometimes it happens, sometimes not.
The more blocks that get mined at the same time, the more likely the bug occurs.

@kyuupichan

This comment has been minimized.

Copy link
Owner

commented Nov 1, 2018

Were you continuing to mine blocks and it didn't reappear? Or did you stop mining, it stayed in bitcoind's mempool, and electrumX still never saw it? Please clarify the sequence of events.

When a block comes in, ElectrumX stops notifying of txs until the block is processed. This is intentional and prevents duplicate notifications and ensures the client always sees a consistent state.

@kyuupichan

This comment has been minimized.

Copy link
Owner

commented Nov 1, 2018

OK so it got in a block, but

  1. there was no notificiation, and
  2. it isn't returned by get_history until restart?

Your post is dense; I'm trying to figure out what happened.

@SomberNight

This comment has been minimized.

Copy link
Contributor Author

commented Nov 1, 2018

OK so it got in a block, but
there was no notificiation, and
it isn't returned by get_history until restart?

Yes. It gets mined, all state in bitcoind seems to be consistent and what we expect.
In ElectrumX, the tx does not appear in scripthash.get_history, and is not reflected by scripthash.subscribe (even if you resubscribe).

(EDIT: from IRC: "after I mine 1000 blocks, when electrumx finishes processing them, it sends me a notification for the scripthash with "null" status ... but that is incorrect, as the tx is mined")

ysangkok added a commit to spesmilo/lightning-integration that referenced this issue Nov 1, 2018

@kyuupichan kyuupichan closed this in 43d576b Nov 1, 2018

kyuupichan added a commit that referenced this issue Nov 1, 2018

Accumulate touched over several blocks
So if several blocks are processed together, the touched
addresses is their union not just the most recent

Fixes #630
@SomberNight

This comment has been minimized.

Copy link
Contributor Author

commented Nov 1, 2018

Thanks, your fix breaks my proof of concept; so that's promising.
To be honest though, I don't understand why this bug needed this many blocks to be mined to manifest. It seems even 2 (?) could have triggered it.

@kyuupichan

This comment has been minimized.

Copy link
Owner

commented Nov 1, 2018

It's because it depends on async scheduling and network timings, I imagine

@kyuupichan

This comment has been minimized.

Copy link
Owner

commented Nov 1, 2018

Unless the blocks are exceedingly close together, which doesn't happen on mainnet and is unlikely even on testnet, it won't trigger. If ElectrumX gets a breather, however slight, it would have sent the notification correctly

@kyuupichan

This comment has been minimized.

Copy link
Owner

commented Nov 1, 2018

Oh, and the history cache is maintained by the code handling address notifications, which is quite natural of course

@SomberNight

This comment has been minimized.

Copy link
Contributor Author

commented Nov 1, 2018

I just find it weird that if I mine 10 blocks "at the same time", that's not enough to trigger it,
but say with 100 blocks, there's a 1/3 chance (extrapolating) it will happen,
and with 1000 blocks, it always seems to happen.

but I guess for example the fact that block processing operates in chunks can introduce all kinds of probabilistic timing factors into this, so not sure it's worth thinking that much about

INFO:Prefetcher:new block height 14,049 hash 1524bbd8ecb6d90b071e755f058ad93931b067241ccfe6b1e6da7464ba427129
INFO:DB:flush #208 took 0.0s.  Height 14,049 txs: 14,144 (+80)
INFO:BlockProcessor:processed 79 blocks in 0.0s
INFO:MemPool:0 txs touching 0 addresses
INFO:Prefetcher:new block height 14,070 hash 23fddcd89e3ebab6c812dd7475de276abbe29b0c153dd0f187a3b51c520ffdb1
INFO:DB:flush #209 took 0.0s.  Height 14,070 txs: 14,165 (+21)
INFO:BlockProcessor:processed 21 blocks in 0.0s
INFO:ElectrumX:[0] notified of 2 addresses

^ those 100 blocks were mined via a single bitcoin-cli command; that's what I mean by chunks

I'm not familiar enough with this part of the electrumx code. :)

@kyuupichan

This comment has been minimized.

Copy link
Owner

commented Nov 2, 2018

It depends on precise mempool refresh timing too; so there's a lot of randomness to it unfortunately.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
2 participants
You can’t perform that action at this time.