fix(electrum): fixed chain sync issue by LagginTimes · Pull Request #1145 · bitcoindevkit/bdk

LagginTimes · 2023-10-03T10:13:40Z

Description

This may or may not fix #1125.
Fixed what appeared to be a logic error in construct_update_tip in electrum_ext.rs that caused the local chain tip to always be a block behind the newest confirmed block.

Checklists

All Submissions:

I've signed all my commits
I followed the contribution guidelines
I ran cargo fmt and cargo clippy before committing

Bugfixes:

This pull request breaks the existing API
I've added tests to reproduce the issue which are now passing
I'm linking the issue being fixed by this PR

danielabrozzoni

ACK 330dfc5

This PR is obviously fixing a bug we hadn't noticed. However, I can still reproduce the bug in #1125, can you please remove the "Fixes #1125" from the PR description, so that merging this PR won't close that issue?

danielabrozzoni · 2023-10-03T14:11:53Z

I've added a debug print:

diff --git a/crates/electrum/src/electrum_ext.rs b/crates/electrum/src/electrum_ext.rs
index 1ce16627..759732da 100644
--- a/crates/electrum/src/electrum_ext.rs
+++ b/crates/electrum/src/electrum_ext.rs
@@ -313,6 +313,7 @@ fn construct_update_tip(
             .map(|h| h.block_hash());
         (start_height..).zip(hashes).collect::<BTreeMap<u32, _>>()
     };
+    println!("Found blocks: {:?}", new_blocks);
 
     // Find the "point of agreement" (if any).
     let agreement_cp = {

I then sent some signet coins to my address, the txid of the transaction is e32872ad281f7d7e3097915364fcb33292e98f537594b17c1333c6151e88821d, which got included in block 163333. As you can see from my console logs, electrum is fetching that block correctly, but still signaling my coins as unconfirmed:

bdk/example-crates/example_electrum git:330dfc5f*  21s
❯ cargo run "tr([e6aebb7c/86'/1'/0']tpubDDHbqK7MNzBYe6eBXLk3C2h4LvHjjRpn5dcU6wXucfYKY4jmLSJdGrwVkoebQCo7hAX5wBN5J7egjn9zmziii7Dnk6H4K4rdMa5ASkBfjTA/0/*)#w067cefw" sync
   Compiling bdk_electrum v0.3.0 (/home/daniela/Developer/bitcoindevkit/bdk/crates/electrum)
   Compiling example_electrum v0.2.0 (/home/daniela/Developer/bitcoindevkit/bdk/example-crates/example_electrum)
    Finished dev [unoptimized + debuginfo] target(s) in 6.15s
     Running `/home/daniela/Developer/bitcoindevkit/bdk/target/debug/example_electrum 'tr([e6aebb7c/86'\''/1'\''/0'\'']tpubDDHbqK7MNzBYe6eBXLk3C2h4LvHjjRpn5dcU6wXucfYKY4jmLSJdGrwVkoebQCo7hAX5wBN5J7egjn9zmziii7Dnk6H4K4rdMa5ASkBfjTA/0/*)#w067cefw' sync`
Checking if e32872ad281f7d7e3097915364fcb33292e98f537594b17c1333c6151e88821d is confirmed yet
Checking if outpoint 39842cb8e85ba3eb1f0deb7c14c3b58d4bdf2c3e3ab0844b4b626bbf1811b602:1 (value: 10000) has been spent
Checking if outpoint c49d5cce814421a01cdbb29ab2eefa0173e3aa918bdea4f12fe06bd0767b9a8a:1 (value: 10000) has been spent
Checking if outpoint 920d767ab89802ed88bbf26694822e552361b0f4dedf015cb44875f1fd1379b7:0 (value: 10000) has been spent
Checking if outpoint 9e15d5edc7c86f49d9900602dffdf7aeb0c781650b4f71a72dcd2472464fa806:1 (value: 10000) has been spent
Checking if outpoint 8cfe68d5232a485934bcfdc75c7ee1c557609367c7e335b5caa0ede9a018ef2e:1 (value: 772111) has been spent
Checking if outpoint 6eaac3103747672aa7c94774f778dcfc13a7912c0b3defbfbca562254f502703:0 (value: 1000000) has been spent
Checking if outpoint e32872ad281f7d7e3097915364fcb33292e98f537594b17c1333c6151e88821d:0 (value: 100000) has been spent
Found blocks: {163326: 0x00000037a1a1c95c7472652187595955674ec606d0004c92e78602aa6ef85c4f, 163327: 0x00000111d2c61452ad6b229ff13de01d21716d20bdf1bc664a06559daccd43fa, 163328: 0x0000009271a874aff0d7e6505f48e7c1f719669758804cd0c08e8887c33da65d, 163329: 0x000000a62e8d8e362b752ed88149a450cb7efc0cfb3491fb0e21384d34bad682, 163330: 0x00000062751143494f1b1c11e9125672458e980cf595f5550cdb7268cf42cbbd, 163331: 0x00000027b0cb80853d344154e19638bffe7718399a0f390bc4768818fa127177, 163332: 0x000000f40eab5125afb8c5911cce195b4b8b4e4a891b369ac2f617cbd1b08e25, 163333: 0x00000109bd7c77fe39d610a9ccd49293173ac0285fadbb53205261ef7ad5d58d}
Checking if address tb1p4h0lgeu7s5typtyxa5swfn83jv4xyr87g5kq9l5j0lrrzmfhxffstraf9g (External, 4) has been used
Checking if address tb1p5x8rtce74p9x5d02wggc6y6swmfxq2r98cmjl4dzs2nnevrdps8sw4ypqm (External, 5) has been used
Checking if address tb1pygqqvg9fajajcrdjdms5vcr3kafz3x05nytg04j0k9an9xghej7sccn0vl (External, 6) has been used
Checking if address tb1puzy3qt29a3velu9de3k263lzj7hs2jsyk57mkpx4squhxm4yza5sgpgquw (External, 7) has been used
Checking if address tb1prq9s35lv0t4z4w8v36k4hsut9dypsw092s7a709nyetmqj7expgsh8xkaa (External, 8) has been used
Checking if address tb1p42am4wed0nfqkumv8r8k28ckxaa5kh34f4rpj39n8z7u9kcqd9lqunkwg7 (External, 9) has been used
                                                                                              
bdk/example-crates/example_electrum git:330dfc5f*  13s
❯ cargo run "tr([e6aebb7c/86'/1'/0']tpubDDHbqK7MNzBYe6eBXLk3C2h4LvHjjRpn5dcU6wXucfYKY4jmLSJdGrwVkoebQCo7hAX5wBN5J7egjn9zmziii7Dnk6H4K4rdMa5ASkBfjTA/0/*)#w067cefw" balance
    Finished dev [unoptimized + debuginfo] target(s) in 0.18s
     Running `/home/daniela/Developer/bitcoindevkit/bdk/target/debug/example_electrum 'tr([e6aebb7c/86'\''/1'\''/0'\'']tpubDDHbqK7MNzBYe6eBXLk3C2h4LvHjjRpn5dcU6wXucfYKY4jmLSJdGrwVkoebQCo7hAX5wBN5J7egjn9zmziii7Dnk6H4K4rdMa5ASkBfjTA/0/*)#w067cefw' balance`
confirmed:
    total           1812111 sats
    spendable       1812111 sats
    immature              0 sats
unconfirmed:
    total            100000 sats
    trusted               0 sats
    untrusted        100000 sats

LagginTimes · 2023-10-03T14:44:56Z

With this patch applied, what I saw is that after the transaction is confirmed in the block on signet, I sometimes would have to sync 2-3 times for the balance to show 0 unconfirmed sats. Before the patch, what I saw was that the local chain tip was always a block behind, so the balance would always show unconfirmed sats until after the second confirmation (again, sometimes requiring running sync 2-3 times).

Console output after 1 confirmation:

laggintimes@lagginx1yoga:~/dev/bdk/example-crates/example_electrum$ cargo run -- sync
    Finished dev [unoptimized + debuginfo] target(s) in 0.03s
     Running `/home/laggintimes/dev/bdk/target/debug/example_electrum sync`
Checking if f775acb5acefbff8e5cc0504fb1ae96a3c2c69dbd9c0254b354abf1acd5aa163 is confirmed yet
Checking if outpoint c2d174cfdb1f73672cc3b844202ba80f14f705c99591b7a3f7881ab5be950c3e:1 (value: 675933) has been spent
Checking if outpoint f775acb5acefbff8e5cc0504fb1ae96a3c2c69dbd9c0254b354abf1acd5aa163:1 (value: 1284128) has been spent
Checking if address tb1p3p244v2az60g98l777faus3vs9r0avy3x9a8kxn900r2wd6l87tswwcx34 (External, 52) has been used
Checking if address tb1p3m9d6cqq9ddnd34463jmkdmw58gvu374y8pvh9wv0cxsjazmyjpqwk8ngh (External, 53) has been used
laggintimes@lagginx1yoga:~/dev/bdk/example-crates/example_electrum$ cargo run -- balance
    Finished dev [unoptimized + debuginfo] target(s) in 0.04s
     Running `/home/laggintimes/dev/bdk/target/debug/example_electrum balance`
confirmed:
    total            675933 sats
    spendable        675933 sats
    immature              0 sats
unconfirmed:
    total           1284128 sats
    trusted         1284128 sats
    untrusted             0 sats
laggintimes@lagginx1yoga:~/dev/bdk/example-crates/example_electrum$ cargo run -- sync
    Finished dev [unoptimized + debuginfo] target(s) in 0.03s
     Running `/home/laggintimes/dev/bdk/target/debug/example_electrum sync`
Checking if f775acb5acefbff8e5cc0504fb1ae96a3c2c69dbd9c0254b354abf1acd5aa163 is confirmed yet
Checking if outpoint c2d174cfdb1f73672cc3b844202ba80f14f705c99591b7a3f7881ab5be950c3e:1 (value: 675933) has been spent
Checking if outpoint f775acb5acefbff8e5cc0504fb1ae96a3c2c69dbd9c0254b354abf1acd5aa163:1 (value: 1284128) has been spent
Checking if address tb1p3p244v2az60g98l777faus3vs9r0avy3x9a8kxn900r2wd6l87tswwcx34 (External, 52) has been used
Checking if address tb1p3m9d6cqq9ddnd34463jmkdmw58gvu374y8pvh9wv0cxsjazmyjpqwk8ngh (External, 53) has been used
laggintimes@lagginx1yoga:~/dev/bdk/example-crates/example_electrum$ cargo run -- balance
    Finished dev [unoptimized + debuginfo] target(s) in 0.04s
     Running `/home/laggintimes/dev/bdk/target/debug/example_electrum balance`
confirmed:
    total           1960061 sats
    spendable       1960061 sats
    immature              0 sats
unconfirmed:
    total                 0 sats
    trusted               0 sats
    untrusted             0 sats

danielabrozzoni · 2023-10-03T15:00:24Z

I can try again later, I just wanted to say, I'm not opposed to merging the PR, I just want to make sure that it actually fixes the issue before closing it. I tried syncing multiple times and while the tx had only one confirmation it would still show up as unconfirmed.

LagginTimes · 2023-10-03T15:02:08Z

Hmm. Maybe @evanlinjin can see if this fixes the bug in his environment?

danielabrozzoni · 2023-10-03T18:37:37Z

If I'm wrong, and after merging this PR nobody is able to reproduce the bug again, we can just close the issue and calling it a day; but I'd like to be sure before closing.

I've reproduced the bug again:

I've sent a transaction with txid 7970f2b095bb1669be8c3a25e2ed5ea603653135968da2f86d557559a84d6ba2, the chain tip was 163,359
Scan wouldn't see the transaction (this needs to be investigated, I'm not sure whether this is a bug or not at the moment, either case, "sync" and "scan" need to be better documented/defined), sync saw an unconfirmed transaction
Block 163,360 came in, including my transaction, but sync/scan wouldn't confirm it
Electrum saw the tx as confirmed when block 163,361 came in.

crates/electrum/src/electrum_ext.rs

LLFourn · 2023-10-03T23:06:09Z

WRT to whether there's still an issue. Can we write a test against electrsd to demonstrate it does fix at least one issue?

LLFourn · 2023-10-03T23:32:10Z

See also earlier PR from @vladimirfomene to add tests: https://github.com/bitcoindevkit/bdk/pull/979/files
It'd be interesting to know if test in #979 would have caught this bug.

nondiremanuel · 2023-10-10T12:13:45Z

Replaced by #1163. We will close this PR when that one is merged

evanlinjin · 2023-10-11T06:37:46Z

Replaced by #1163. We will close this PR when that one is merged

I've closed #1163 as I agree with @LLFourn's points and we can update the bug fixes to electrum crate separately.

@LagginTimes I think the next steps should be

Update fix to how @LLFourn suggested it.
Copy and paste TestEnv and write tests for electrum.

danielabrozzoni · 2023-10-11T09:46:33Z

Since I'm the only one being able to reproduce the bug still, do you need help with debugging? :)

LagginTimes · 2023-11-08T21:37:04Z

Rebased with #1182 CI fixes.

Fixed a logic error in `construct_update_tip` in `electrum_ext.rs` that caused the local chain tip to always be a block behind the newest confirmed block.

LagginTimes · 2023-11-11T20:27:34Z

WRT to whether there's still an issue. Can we write a test against electrsd to demonstrate it does fix at least one issue?

A chain sync test was written as part of #1171 that successfully reproduced the issue described in #1125. This PR seems to at least partially fix #1125 w.r.t. patching a logical flaw that was confirmed with the #1171 test. However, I am uncertain if it fixes @danielabrozzoni's issue that both @evanlinjin and I have unfortunately been unable to reproduce.

danielabrozzoni

ACK 1010efd - although I've been able to reproduce the issue in #1125, I'm convinced that this PR fixes at least a bug, as demonstrated in #1171 (yet to be reviewed and merged).

LagginTimes force-pushed the example_electrum_sync branch from 07d282f to 330dfc5 Compare October 3, 2023 10:19

notmandatory assigned LagginTimes Oct 3, 2023

notmandatory added the bug Something isn't working label Oct 3, 2023

notmandatory added this to the 1.0.0-alpha.3 milestone Oct 3, 2023

danielabrozzoni approved these changes Oct 3, 2023

View reviewed changes

LLFourn reviewed Oct 3, 2023

View reviewed changes

crates/electrum/src/electrum_ext.rs Outdated Show resolved Hide resolved

LLFourn mentioned this pull request Oct 3, 2023

Test electrum ext #979

Closed

3 tasks

nondiremanuel mentioned this pull request Oct 6, 2023

W41 Lib Team Call bitcoindevkit/.github#80

Closed

39 tasks

evanlinjin mentioned this pull request Oct 10, 2023

fix(electrum): fixed chain sync issue #1163

Closed

4 tasks

LagginTimes marked this pull request as draft October 15, 2023 15:55

nondiremanuel mentioned this pull request Oct 22, 2023

W43 Lib Team Call bitcoindevkit/.github#83

Closed

33 tasks

nondiremanuel mentioned this pull request Nov 5, 2023

W45 Lib Team Call bitcoindevkit/.github#84

Closed

38 tasks

LagginTimes force-pushed the example_electrum_sync branch from 330dfc5 to d58f13d Compare November 8, 2023 21:35

fix(electrum): fixed chain sync issue

1010efd

Fixed a logic error in `construct_update_tip` in `electrum_ext.rs` that caused the local chain tip to always be a block behind the newest confirmed block.

LagginTimes force-pushed the example_electrum_sync branch from d58f13d to 1010efd Compare November 11, 2023 12:53

LagginTimes mentioned this pull request Nov 11, 2023

chore: extract TestEnv into separate crate #1171

Merged

3 tasks

LagginTimes marked this pull request as ready for review November 11, 2023 23:28

danielabrozzoni approved these changes Nov 13, 2023

View reviewed changes

danielabrozzoni merged commit 855c61a into bitcoindevkit:master Nov 13, 2023

danielabrozzoni mentioned this pull request Nov 13, 2023

Calling example_electrum sync on an unconfirmed tx may result in the tx being stuck as unconfirmed eternally (according to the cli)) #1125

Closed

LagginTimes mentioned this pull request Nov 16, 2023

bdk + esplora update_local_chain logic might be off #1199

Closed

nondiremanuel mentioned this pull request Nov 19, 2023

W47 Lib Team Call bitcoindevkit/.github#86

Closed

54 tasks

notmandatory mentioned this pull request Jan 3, 2024

Release 1.0.0-alpha.3 #1254

Closed

12 tasks

Conversation

LagginTimes commented Oct 3, 2023 • edited by danielabrozzoni Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Description

Checklists

All Submissions:

Bugfixes:

Uh oh!

danielabrozzoni left a comment

Choose a reason for hiding this comment

Uh oh!

danielabrozzoni commented Oct 3, 2023

Uh oh!

LagginTimes commented Oct 3, 2023

Uh oh!

danielabrozzoni commented Oct 3, 2023

Uh oh!

LagginTimes commented Oct 3, 2023

Uh oh!

danielabrozzoni commented Oct 3, 2023

Uh oh!

Uh oh!

LLFourn commented Oct 3, 2023

Uh oh!

LLFourn commented Oct 3, 2023

Uh oh!

nondiremanuel commented Oct 10, 2023

Uh oh!

evanlinjin commented Oct 11, 2023

Uh oh!

danielabrozzoni commented Oct 11, 2023

Uh oh!

LagginTimes commented Nov 8, 2023

Uh oh!

LagginTimes commented Nov 11, 2023

Uh oh!

danielabrozzoni left a comment

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants

LagginTimes commented Oct 3, 2023 •

edited by danielabrozzoni

Loading