search

romanz / electrs

An efficient re-implementation of Electrum Server in Rust
MIT License
1.1k stars 408 forks source link

Bug: electrs hangs on `get_history` #1069

Open su-sd opened 3 months ago

su-sd commented 3 months ago

Describe the bug I want to get information about addresses (balances, transactions) via a custom script. While getting information of some addresses with a lot of transactions, electrs hangs, while there is no load on the cpu, disk or bitcoind. Even Ctrl+C and kill does not work anymore.

Electrs version 603830f1b921928089c558d90519b7ca0c0d4658 Tag v0.10.5

To Reproduce

  1. Configure and start electrs
  2. Connect with custom client
  3. Call blockchain.scripthash.subscribe b3308ec9eb6b94b333e6aba375f681ad5a9630e823eb82c68e3f1cc38f9ea3fa or alternative
  4. Call blockchain.scripthash.get_history b3308ec9eb6b94b333e6aba375f681ad5a9630e823eb82c68e3f1cc38f9ea3fa

Expected behavior A response and no hang

Configuration electrs --ignore-mempool --network bitcoin --log-filters debug

System running electrs

Electrum client custom script

Additional context Log file of electrum:

Starting electrs 0.10.5 on x86_64 linux with Config { network: Bitcoin, db_path: "./db/bitcoin", db_log_dir: None, daemon_dir: "/home/electrum/.bitcoin", daemon_auth: CookieFile("/home/electrum/.bitcoin/.cookie"), daemon_rpc_addr: 127.0.0.1:8332, daemon_p2p_addr: 127.0.0.1:8333, electrum_rpc_addr: 127.0.0.1:50001, monitoring_addr: 127.0.0.1:4224, wait_duration: 10s, jsonrpc_timeout: 15s, index_batch_size: 10, index_lookup_limit: None, reindex_last_blocks: 0, auto_reindex: true, ignore_mempool: true, sync_once: false, skip_block_download_wait: false, disable_electrum_rpc: false, server_banner: "Welcome to electrs 0.10.5 (Electrum Rust Server)!", signet_magic: f9beb4d9, args: [] }
[2024-08-10T19:07:01.295Z DEBUG tiny_http] Server listening on 127.0.0.1:4224
[2024-08-10T19:07:01.296Z INFO  electrs::metrics::metrics_impl] serving Prometheus metrics on 127.0.0.1:4224
[2024-08-10T19:07:01.296Z INFO  electrs::server] serving Electrum RPC on 127.0.0.1:50001
[2024-08-10T19:07:01.296Z DEBUG tiny_http] Running accept thread
[2024-08-10T19:07:01.321Z INFO  electrs::db] "./db/bitcoin": 194 SST files, 49.010265499 GB, 6.135426344 Grows
[2024-08-10T19:07:01.322Z DEBUG electrs::db] DB Some(Config { compacted: true, format: 0 })
[2024-08-10T19:07:01.345Z DEBUG electrs::db] auto-compactions enabled
[2024-08-10T19:07:02.860Z INFO  electrs::chain] loading 856201 headers, tip=0000000000000000000190c29c8dded4505059eb9bb3a973535611be782b3465
[2024-08-10T19:07:03.932Z INFO  electrs::chain] chain updated: tip=0000000000000000000190c29c8dded4505059eb9bb3a973535611be782b3465, height=856201
[2024-08-10T19:07:03.942Z DEBUG bitcoincore_rpc] JSON-RPC request: getblockchaininfo []
[2024-08-10T19:07:03.944Z DEBUG bitcoincore_rpc] JSON-RPC request: getnetworkinfo []
[2024-08-10T19:07:03.944Z DEBUG bitcoincore_rpc] JSON-RPC request: getnetworkinfo []
[2024-08-10T19:07:03.945Z DEBUG bitcoincore_rpc] JSON-RPC request: getblockchaininfo []
[2024-08-10T19:07:03.945Z DEBUG bitcoincore_rpc] JSON-RPC request: getnetworkinfo []
[2024-08-10T19:07:03.947Z DEBUG electrs::p2p] peer version: VersionMessage { version: 70016, services: ServiceFlags(3081), timestamp: 1723316823, receiver: Address {services: ServiceFlags(NONE), address: 0.0.0.0, port: 0}, sender: Address {services: ServiceFlags(NETWORK|WITNESS|NETWORK_LIMITED|P2P_V2), address: 0.0.0.0, port: 0}, nonce: 12289463789444946264, user_agent: "/Satoshi:27.1.0/", start_height: 856201, relay: false }
[2024-08-10T19:07:03.947Z DEBUG electrs::p2p] got 0 new headers
[2024-08-10T19:07:13.949Z DEBUG electrs::p2p] got 0 new headers
[2024-08-10T19:07:23.949Z DEBUG electrs::p2p] got 0 new headers
[2024-08-10T19:07:26.647Z DEBUG electrs::server] 0: recv [{"method": "blockchain.scripthash.subscribe", "params": ["b3308ec9eb6b94b333e6aba375f681ad5a9630e823eb82c68e3f1cc38f9ea3fa"], "id": 0, "jsonrpc": "2.0"}]
[2024-08-10T19:07:26.647Z DEBUG electrs::server] 0: connected
[2024-08-10T19:07:26.683Z DEBUG electrs::p2p] loading 70101 blocks
[2024-08-10T19:18:13.689Z INFO  electrs::signals] notified via SIG2
[2024-08-10T19:18:14.953Z INFO  electrs::signals] notified via SIG2

Edit: I know the time-span in the log is short, but it really hangs for hours. An example address is: 1NDyJtNTjmwk5xPNhjgAMu4HDHigtobu1s If there is a way to know in advance if a query will hang, it would be a ok-ish workaround for me.

su-sd commented 3 months ago

This is easy reproducible with blockchain.scripthash.get_history scripthash(1N52wHoVR79PMDishab2XmRHsbekCdGquK)

su-sd commented 3 months ago

Here is another example with bc1qns9f7yfx3ry9lj6yz7c9er0vwa0ye2eklpzqfw

[2024-08-11T15:00:04.028Z DEBUG electrs::server] 0: recv [{"method": "blockchain.scripthash.get_history", "params": ["ebd807b46f054cd4a2ea8c4c4f325511cad063ab4b69787e8031f
92d47d425bb"], "id": 40674, "jsonrpc": "2.0"}]                                                                                                                             
[2024-08-11T15:00:04.028Z INFO  electrs::electrum] your wallet uses less efficient method of querying electrs, consider contacting the developer of your wallet. Reason: bl
ockchain.scripthash.get_history called for unsubscribed scripthash                                                                                                         
[2024-08-11T15:00:04.768Z DEBUG electrs::p2p] loading 94122 blocks                                                                                                         
[2024-08-11T15:19:28.344Z DEBUG electrs::p2p] peer inventory: [Block(00000000000000000001b351689ae3ae114faa4e0dd163e0db86e3fadee9f4d0)]                                    
[2024-08-11T15:21:38.342Z DEBUG electrs::p2p] peer inventory: [Block(000000000000000000025dff7e937edc02430475f8f6f554a713871d163b8bc5)]                                    
[2024-08-11T15:23:32.912Z DEBUG electrs::p2p] peer inventory: [Block(000000000000000000015d1de9bb416b0c7a6d851f778039a97173760a871f72)]                                    
[2024-08-11T15:38:02.617Z DEBUG electrs::p2p] peer inventory: [Block(00000000000000000002824582dbe544a676dc7d20750528eda0949064d92fb3)]                                    
[2024-08-11T16:15:10.472Z DEBUG electrs::p2p] peer inventory: [Block(0000000000000000000285c411d7caf77713816ac9e90d432d0c429b3be25cd5)]                                    
[2024-08-11T16:33:09.052Z DEBUG electrs::p2p] peer inventory: [Block(000000000000000000017a72beac7a847a8d6ac0b223dd19c948402e431cf048)]                                    
[2024-08-11T16:41:25.530Z DEBUG electrs::p2p] peer inventory: [Block(000000000000000000023e938a070a12ea9cfeb57521f0149dc9ec3c5bd2f8b9)]                                    
[2024-08-11T17:06:05.215Z DEBUG electrs::p2p] peer inventory: [Block(0000000000000000000225c2bf40fe1eaef5a68d9969e63981f94a6d7fa8628a)]                                    
[2024-08-11T17:11:12.310Z DEBUG electrs::p2p] peer inventory: [Block(000000000000000000017a3748deeb55a70c4886c720d2d3e8f2b4f7ea21b7d9)]                                    
[2024-08-11T17:14:05.785Z DEBUG electrs::p2p] peer inventory: [Block(0000000000000000000019aa89eef8d4b0371e456f708e8c77e18a2b0e2fb399)]                                    
[2024-08-11T17:18:48.579Z DEBUG electrs::p2p] peer inventory: [Block(00000000000000000002899d62e12e6b340cd3702aa5e6ccdc310fffe99c11d0)]                                    
[2024-08-11T17:25:29.180Z DEBUG electrs::p2p] peer inventory: [Block(00000000000000000002cff8c706688141ca23224c1ab4d7350f318116b0de67)]                                    
[2024-08-11T17:30:58.206Z DEBUG electrs::p2p] peer inventory: [Block(00000000000000000001ad283d7bbc965a232854493f13c63af51f370e871212)]                                    
[2024-08-11T17:32:52.203Z DEBUG electrs::p2p] peer inventory: [Block(00000000000000000000b9ca04bc744f399c577e17522b7146ee318a39b2d156)]                                    
[2024-08-11T17:34:48.550Z DEBUG electrs::p2p] peer inventory: [Block(000000000000000000027cabe9070ec5cbfa990ccc76fac6e89958d6b3d9fa06)]                                    
[2024-08-11T17:55:16.443Z DEBUG electrs::p2p] peer inventory: [Block(00000000000000000000db0aded65742c993e372531d69e2d2083083bdc2be9f)]                                    
[2024-08-11T17:55:20.291Z DEBUG electrs::p2p] peer inventory: [Block(00000000000000000001e954f726f3cfa5ba0f878f9f2f028a9de0c1f4581360)]                                    
[2024-08-11T18:02:54.422Z DEBUG electrs::p2p] peer inventory: [Block(000000000000000000017d21a993457c2d56a489871a89718b35b1973426c1e3)]
[2024-08-11T18:07:21.416Z DEBUG electrs::p2p] peer inventory: [Block(00000000000000000000a082762d3339801548628d7ca47422a54f6a268c8359)]
[2024-08-11T18:16:33.594Z DEBUG electrs::p2p] peer inventory: [Block(0000000000000000000135b0a6cddcd0d238ab4479f21300a1c9a8f5c5706ac4)]
[2024-08-11T18:22:26.783Z DEBUG electrs::p2p] peer inventory: [Block(00000000000000000002b07b00e82759d6a5fc201262d706012be265137a839c)]
[2024-08-11T18:22:50.967Z DEBUG electrs::p2p] peer inventory: [Block(00000000000000000000abfbffef49a2f1615fee4e6e55546725eac2da03e763)]
[2024-08-11T18:34:42.866Z DEBUG electrs::p2p] peer inventory: [Block(00000000000000000000ad2e4ef6766fa2e9d1542d2fbe8ebb4b1cf7c6178b2d)]
[2024-08-11T18:35:38.968Z DEBUG electrs::p2p] peer inventory: [Block(000000000000000000004b825c3e5eb8c87decbf1310e99833ef64fb2ea7b9c1)]
[2024-08-11T18:38:06.894Z DEBUG electrs::p2p] peer inventory: [Block(000000000000000000024e0e17c7ad98a2b234210bcc4e14e69cd1c912168606)]
[2024-08-11T18:40:48.117Z DEBUG electrs::p2p] peer inventory: [Block(00000000000000000002c6943042a688f6406de11178ff431c4f1881857fbb5c)]
[2024-08-11T18:41:30.650Z DEBUG electrs::p2p] peer inventory: [Block(00000000000000000000c91b1ff979d821b79b9b54cf4984bbcae786bb63fd8b)]
[2024-08-11T18:41:54.476Z DEBUG electrs::p2p] peer inventory: [Block(000000000000000000001e0fc913f26f833bd2b2131b6032174291b409d6a14a)]
[2024-08-11T19:11:42.223Z DEBUG electrs::p2p] peer inventory: [Block(000000000000000000006694f460aab082bf0a5680c085c07330de3ac0ff5dfc)]
[2024-08-11T19:16:34.047Z DEBUG electrs::p2p] peer inventory: [Block(00000000000000000001bbab8f806e2e08a213b3c678489f94bc638d94419fc7)]
[2024-08-11T19:18:15.010Z DEBUG electrs::p2p] peer inventory: [Block(00000000000000000000371b78892f266b601ac581db9881a1e3ea39a47c615c)]
[2024-08-11T19:23:58.762Z DEBUG electrs::p2p] peer inventory: [Block(00000000000000000002f97202159aa78d6168408d9b4211cc4572b0652810ba)]
[2024-08-11T19:26:56.273Z DEBUG electrs::p2p] peer inventory: [Block(00000000000000000002d49d01f5ac7c439ae8bb71718c22a4bd86b53bf3e6fb)]
[2024-08-11T19:29:23.520Z DEBUG electrs::p2p] peer inventory: [Block(000000000000000000008107ecbe1788f2ca81865f2e7e2870e1a68a8dfeed97)]
[2024-08-11T19:39:10.428Z DEBUG electrs::p2p] peer inventory: [Block(0000000000000000000218087c742b691d4fb3a2678268233eeb3992cef8f619)]
^C[2024-08-11T19:58:04.967Z INFO  electrs::signals] notified via SIG2
romanz commented 3 months ago

https://mempool.space/address/1NDyJtNTjmwk5xPNhjgAMu4HDHigtobu1s has >1M txs. https://mempool.space/address/bc1qns9f7yfx3ry9lj6yz7c9er0vwa0ye2eklpzqfw has >500M txs. https://mempool.space/address/1N52wHoVR79PMDishab2XmRHsbekCdGquK has > 400k txs.

Currently, electrs will take quite a while to compute the history for such "popular" addresses - since it fetches whole blocks from bitcoind and applies client-side parsing to find the relevant transactions (see https://www.sparrowwallet.com/docs/server-performance.html for more details).

romanz commented 3 months ago

If there is a way to know in advance if a query will hang, it would be a ok-ish workaround for me.

@su-sd You can use index_lookup_limit config flag (e.g. to 1000) to cause the lookup to fail on such addresses: https://github.com/romanz/electrs/blob/831ab0a5252034e3c766e9164406ceb40cd29b3a/internal/config_specification.toml#L121-L125

su-sd commented 3 months ago

@romanz Thank you very much, I'll try that parameter. I still think there is a bug, since there is no load on the cpu or disk. Usually when electrs states, that it is loading 19230 blocks, bitcoind and electrs cause at least 3 cpu-cores to be utilized.

romanz commented 3 months ago

Reproduced using ./history.py bc1qns9f7yfx3ry9lj6yz7c9er0vwa0ye2eklpzqfw - it seems that electrs is sending a request which is too large - and gets disconnected (in my case):

$ bitcoind -debug=net
...
2024-08-12T18:55:09Z [net] received: getheaders (997 bytes) peer=2
2024-08-12T18:55:09Z [net] getheaders -1 to end from peer=2
2024-08-12T18:55:09Z [net] sending headers (1 bytes) peer=2
2024-08-12T18:55:10Z [net] received: getdata (3393293 bytes) peer=2
2024-08-12T18:55:10Z [net] Misbehaving: peer=2: getdata message size = 94258
2024-08-12T18:55:10Z [net] Warning: disconnecting but not discouraging local peer 2!
2024-08-12T18:55:10Z [net] disconnecting peer=2
2024-08-12T18:55:10Z [net] Cleared nodestate for peer=2

electrs log:

[2024-08-12T18:55:10.156Z WARN  electrs::electrum] RPC blockchain.scripthash.subscribe failed: failed to get block 000000000000000000057d3d2981bade313ce211cc4466a153e7fe03990e2408: receiving on an empty and disconnected channel
[2024-08-12T18:55:10.156Z INFO  electrs::db] closing DB at ./db/bitcoin