cake_wallet icon indicating copy to clipboard operation
cake_wallet copied to clipboard

Published 20 hours ago • verified publisher icon cake-tech

Won't sync with Electrs (BTC)

Open mariodian opened this issue 4 years ago • 2 comments

I'm using the latest Electrs 0.9.2 and when I connect Cake Wallet to it, it gets stuck on "Starting Sync". When I switch to Cake Wallet's ElectrumX (or any ElectrumX for that matter) it synchronizes instantly.

Upon checking my Electrs logs, I see that Cake Wallet does not subscribe for a script hash (not sure if this is necessary these days):

blockchain.scripthash.get_history called for unsubscribed scripthash

and these messages are what the wallet gets stuck on. It doesn't show any transactions nor the balance, it just prentends to keep syncing. Although, on the Electrs side, I see that it sees wallet related transactions, cake wallet just doesn't react to it.

I'm using Cake Wallet 4.2.7 on iOS 15.1

I will report to Electrs too because it might as well be server related issue (although other wallets /blue, sparrow, electrum/ work fine with my Electrs).

mariodian avatar Nov 03 '21 03:11 mariodian

Upon further investigation it seems (and my Electrs logs think so too - although I may be wrong, this is the first time I'm seeing Dart) that the synchronization process is called twice.

Full electrs log:

[2021-11-04T02:28:47.787Z INFO  electrs::chain] loading 708110 headers, tip=0000000000000000000a7e7c1e44d02b71295729133d6314c135314511ee743d
[2021-11-04T02:28:49.493Z DEBUG electrs::server] 1: recv {"jsonrpc": "2.0", "method": "blockchain.scripthash.get_balance", "id": "425",  "params": ["322...281"]}
[2021-11-04T02:28:49.493Z DEBUG electrs::server] 1: recv {"jsonrpc": "2.0", "method": "blockchain.scripthash.get_balance", "id": "426",  "params": ["183...0a8"]}
[2021-11-04T02:28:49.493Z DEBUG electrs::server] 1: recv {"jsonrpc": "2.0", "method": "blockchain.scripthash.get_balance", "id": "427",  "params": ["0f9...7e3"]}
[2021-11-04T02:28:49.493Z DEBUG electrs::server] 1: recv {"jsonrpc": "2.0", "method": "blockchain.scripthash.get_balance", "id": "428",  "params": ["cc3...101"]}
...
[2021-11-04T02:28:49.493Z DEBUG electrs::server] 1: recv {"jsonrpc": "2.0", "method": "blockchain.scripthash.subscribe", "id": "458",  "params": ["322...281"]}
[2021-11-04T02:28:49.493Z DEBUG electrs::server] 1: recv {"jsonrpc": "2.0", "method": "blockchain.scripthash.subscribe", "id": "459",  "params": ["183...0a8"]}
[2021-11-04T02:28:49.493Z DEBUG electrs::server] 1: recv {"jsonrpc": "2.0", "method": "blockchain.scripthash.subscribe", "id": "460",  "params": ["0f9...7e3"]}
[2021-11-04T02:28:49.493Z DEBUG electrs::server] 1: recv {"jsonrpc": "2.0", "method": "blockchain.scripthash.subscribe", "id": "461",  "params": ["cc3...101"]}
...
[2021-11-04T02:28:50.198Z INFO  electrs::chain] chain updated: tip=0000000000000000000a7e7c1e44d02b71295729133d6314c135314511ee743d, height=708110
[2021-11-04T02:28:50.208Z DEBUG electrs::p2p] peer version: VersionMessage { version: 70016, services: ServiceFlags(1033), timestamp: 1635992928, receiver: Address {services: ServiceFlags(NONE), address: 0.0.0.0, port: 0}, sender: Address {services: ServiceFlags(NETWORK|WITNESS|NETWORK_LIMITED), address: 0.0.0.0, port: 0}, nonce: 4634551636598522219, user_agent: "/Satoshi:22.0.0/", start_height: 708110, relay: true }
[2021-11-04T02:28:50.209Z DEBUG electrs::p2p] got 0 new headers
[2021-11-04T02:28:50.237Z DEBUG electrs::mempool] loading 5049 mempool transactions
[2021-11-04T02:28:51.488Z DEBUG electrs::server] 1: recv {"jsonrpc": "2.0", "method": "server.ping", "id": "491",  "params": []}
[2021-11-04T02:28:52.061Z DEBUG electrs::mempool] 5049 mempool txs: 5049 added, 0 removed
[2021-11-04T02:28:52.061Z DEBUG electrs::server] 0: connected
[2021-11-04T02:28:52.061Z DEBUG electrs::server] 1: connected
[2021-11-04T02:28:52.061Z WARN  electrs::electrum] blockchain.scripthash.get_balance called for unsubscribed scripthash: 322...281
[2021-11-04T02:28:52.088Z DEBUG electrs::p2p] loading 3 blocks
[2021-11-04T02:28:52.207Z DEBUG electrs::status] 3 transactions from 3 blocks
[2021-11-04T02:28:52.207Z WARN  electrs::electrum] blockchain.scripthash.get_balance called for unsubscribed scripthash: 183...0a8
[2021-11-04T02:28:52.217Z WARN  electrs::electrum] blockchain.scripthash.get_balance called for unsubscribed scripthash: 0f9...7e3
[2021-11-04T02:28:52.227Z WARN  electrs::electrum] blockchain.scripthash.get_balance called for unsubscribed scripthash: cc3...101
...
[2021-11-04T02:28:52.464Z DEBUG electrs::p2p] loading 3 blocks
[2021-11-04T02:28:52.534Z DEBUG electrs::status] 3 transactions from 3 blocks
[2021-11-04T02:28:52.601Z DEBUG electrs::server] 1: send {"id":"425","jsonrpc":"2.0","result":{"confirmed":5967328,"unconfirmed":0}}
[2021-11-04T02:28:52.601Z DEBUG electrs::server] 1: send {"id":"426","jsonrpc":"2.0","result":{"confirmed":0,"unconfirmed":0}}
[2021-11-04T02:28:52.601Z DEBUG electrs::server] 1: send {"id":"427","jsonrpc":"2.0","result":{"confirmed":0,"unconfirmed":0}}
[2021-11-04T02:28:52.601Z DEBUG electrs::server] 1: send {"id":"428","jsonrpc":"2.0","result":{"confirmed":0,"unconfirmed":0}}
...
[2021-11-04T02:28:52.601Z DEBUG electrs::server] 1: send {"id":"458","jsonrpc":"2.0","result":"d7c...06e"}
[2021-11-04T02:28:52.601Z DEBUG electrs::server] 1: send {"id":"459","jsonrpc":"2.0","result":null}
[2021-11-04T02:28:52.601Z DEBUG electrs::server] 1: send {"id":"460","jsonrpc":"2.0","result":null}
[2021-11-04T02:28:52.601Z DEBUG electrs::server] 1: send {"id":"461","jsonrpc":"2.0","result":null}
...
[2021-11-04T02:28:52.602Z DEBUG electrs::p2p] got 0 new headers
[2021-11-04T02:28:52.619Z DEBUG electrs::mempool] loading 5051 mempool transactions
[2021-11-04T02:28:52.622Z DEBUG electrs::mempool] 5051 mempool txs: 2 added, 0 removed
[2021-11-04T02:28:52.622Z DEBUG electrs::status] 3 transactions from 3 blocks
[2021-11-04T02:28:53.487Z DEBUG electrs::server] 1: recv {"jsonrpc": "2.0", "method": "server.ping", "id": "492",  "params": []}
[2021-11-04T02:28:53.487Z DEBUG electrs::server] 1: send {"id":"492","jsonrpc":"2.0","result":null}
[2021-11-04T02:28:53.488Z DEBUG electrs::p2p] got 0 new headers
[2021-11-04T02:28:53.508Z DEBUG electrs::mempool] loading 5051 mempool transactions
[2021-11-04T02:28:53.509Z DEBUG electrs::mempool] 5051 mempool txs: 0 added, 0 removed
[2021-11-04T02:28:53.509Z DEBUG electrs::status] 3 transactions from 3 blocks
[2021-11-04T02:28:54.182Z DEBUG electrs::server] 2: connected
[2021-11-04T02:28:54.183Z DEBUG electrs::p2p] got 0 new headers
[2021-11-04T02:28:54.220Z DEBUG electrs::mempool] loading 5052 mempool transactions
[2021-11-04T02:28:54.223Z DEBUG electrs::mempool] 5052 mempool txs: 1 added, 0 removed
[2021-11-04T02:28:54.223Z DEBUG electrs::status] 3 transactions from 3 blocks
[2021-11-04T02:28:54.310Z DEBUG electrs::server] 1: disconnected
[2021-11-04T02:28:54.311Z DEBUG electrs::p2p] got 0 new headers
[2021-11-04T02:28:54.352Z DEBUG electrs::mempool] loading 5052 mempool transactions
[2021-11-04T02:28:54.354Z DEBUG electrs::mempool] 5052 mempool txs: 0 added, 0 removed
[2021-11-04T02:28:54.482Z DEBUG electrs::server] 3: connected
[2021-11-04T02:28:54.484Z DEBUG electrs::p2p] got 0 new headers
[2021-11-04T02:28:54.498Z DEBUG electrs::server] 3: recv {"jsonrpc": "2.0", "method": "blockchain.scripthash.get_balance", "id": "493",  "params": ["322...281"]}
[2021-11-04T02:28:54.498Z DEBUG electrs::server] 3: recv {"jsonrpc": "2.0", "method": "blockchain.scripthash.get_balance", "id": "494",  "params": ["183...0a8"]}
[2021-11-04T02:28:54.498Z DEBUG electrs::server] 3: recv {"jsonrpc": "2.0", "method": "blockchain.scripthash.get_balance", "id": "495",  "params": ["0f9...7e3"]}
[2021-11-04T02:28:54.498Z DEBUG electrs::server] 3: recv {"jsonrpc": "2.0", "method": "blockchain.scripthash.get_balance", "id": "496",  "params": ["cc3...101"]}
...
[2021-11-04T02:28:54.499Z DEBUG electrs::server] 3: recv {"jsonrpc": "2.0", "method": "blockchain.scripthash.subscribe", "id": "526",  "params": ["322...281"]}
[2021-11-04T02:28:54.499Z DEBUG electrs::server] 3: recv {"jsonrpc": "2.0", "method": "blockchain.scripthash.subscribe", "id": "527",  "params": ["183...0a8"]}
[2021-11-04T02:28:54.499Z DEBUG electrs::server] 3: recv {"jsonrpc": "2.0", "method": "blockchain.scripthash.subscribe", "id": "528",  "params": ["0f9...7e3"]}
[2021-11-04T02:28:54.499Z DEBUG electrs::server] 3: recv {"jsonrpc": "2.0", "method": "blockchain.scripthash.subscribe", "id": "529",  "params": ["cc3...101"]}
...
[2021-11-04T02:28:54.525Z DEBUG electrs::mempool] loading 5052 mempool transactions
[2021-11-04T02:28:54.528Z DEBUG electrs::mempool] 5052 mempool txs: 0 added, 0 removed
[2021-11-04T02:28:54.528Z WARN  electrs::electrum] blockchain.scripthash.get_balance called for unsubscribed scripthash: 322...281
[2021-11-04T02:28:54.528Z DEBUG electrs::p2p] loading 3 blocks
[2021-11-04T02:28:54.627Z DEBUG electrs::status] 3 transactions from 3 blocks
[2021-11-04T02:28:54.627Z WARN  electrs::electrum] blockchain.scripthash.get_balance called for unsubscribed scripthash: 183...0a8
[2021-11-04T02:28:54.627Z WARN  electrs::electrum] blockchain.scripthash.get_balance called for unsubscribed scripthash: 0f9...7e3
[2021-11-04T02:28:54.627Z WARN  electrs::electrum] blockchain.scripthash.get_balance called for unsubscribed scripthash: cc3...101
...
[2021-11-04T02:28:54.694Z DEBUG electrs::p2p] loading 3 blocks
[2021-11-04T02:28:54.764Z DEBUG electrs::status] 3 transactions from 3 blocks
[2021-11-04T02:28:54.829Z DEBUG electrs::server] 3: send {"id":"493","jsonrpc":"2.0","result":{"confirmed":5967328,"unconfirmed":0}}
[2021-11-04T02:28:54.829Z DEBUG electrs::server] 3: send {"id":"494","jsonrpc":"2.0","result":{"confirmed":0,"unconfirmed":0}}
[2021-11-04T02:28:54.829Z DEBUG electrs::server] 3: send {"id":"495","jsonrpc":"2.0","result":{"confirmed":0,"unconfirmed":0}}
[2021-11-04T02:28:54.829Z DEBUG electrs::server] 3: send {"id":"496","jsonrpc":"2.0","result":{"confirmed":0,"unconfirmed":0}}
...
[2021-11-04T02:28:54.829Z DEBUG electrs::server] 3: send {"id":"526","jsonrpc":"2.0","result":"d7c...06e"}
[2021-11-04T02:28:54.829Z DEBUG electrs::server] 3: send {"id":"527","jsonrpc":"2.0","result":null}
[2021-11-04T02:28:54.829Z DEBUG electrs::server] 3: send {"id":"528","jsonrpc":"2.0","result":null}
[2021-11-04T02:28:54.829Z DEBUG electrs::server] 3: send {"id":"529","jsonrpc":"2.0","result":null}
...

The syncing is first called in startSync():

https://github.com/cake-tech/cake_wallet/blob/e04bf471020b79b13e7a59a63396c132ae6d5f37/lib/bitcoin/electrum_wallet.dart#L118-L125

and then within _subscribeForUpdates() again:

https://github.com/cake-tech/cake_wallet/blob/e04bf471020b79b13e7a59a63396c132ae6d5f37/lib/bitcoin/electrum_wallet.dart#L506-L514

If that's so, that may explain the warning i'm getting on the Electrs side. But it still doesn't explain why Cake isn't showing any transactions and why ElectrumX has no problem with Cake calling the sync process twice.

Also Cake calls the scripthash.get_balance and scripthash.subscribe in the wrong order (it should be subscribe first and then get_balance).

mariodian avatar Nov 04 '21 13:11 mariodian

Same issue that bitcoin wallet will rarely sync with anything other than the cakewallet electrum server. Using cakewallet 4.3.7 on iOS 15.3, connecting to raspibolt running electrs 0.9.4.

Every once in a while (<10% of attempts) it will show synchronized when connected to my electrs server, but most times it just shows "starting sync". The node has a green dot next to it and the test succeeds when adding the node. Even after a "successful" sync, balance will be correct, but the transactions leading to that balance do not show up at all, unless I reconnect to the cakewallet server.

I think the only new information I'm adding is that newer versions of cakewallet, iOS, and electrs show the same behavior as the original post, except that I do occasionally see a synchronized status and updated total balance.

y0urleader avatar Feb 10 '22 14:02 y0urleader