electrumx icon indicating copy to clipboard operation
electrumx copied to clipboard
verified publisher icon spesmilo

Q: regression in end-to-end test after update from v1.16 to v1.18

Open theborakompanioni opened this issue 3 months ago • 2 comments

I have a regression in an e2e test on regtest I cannot quite pinpoint when updating from v1.16 to v1.18. No changes would indicate to me that there could be a problem or that there is a connection to what can be observed.

Test setup: Running on regtest, regularly mining blocks to an address. On maturity, send them to a different wallet and verify the incoming tx. Works without issues with electrum daemon v4.6.2 and electrumx v1.16, but starts to fail with v1.18 - success and failure are reproducible. Maybe someone can point me into the right direction?

Logs from v1.16:

INFO:electrumx:ElectrumX server starting
INFO:electrumx:logging level: DEBUG
INFO:Controller:Python version: 3.7.9 (default, Dec 18 2020, 05:56:48)  [GCC 9.3.0]
INFO:Controller:software version: ElectrumX 1.16.0
INFO:Controller:aiorpcX version: 0.18.7
INFO:Controller:supported protocol versions: 1.4-1.4.2
INFO:Controller:event loop policy: <uvloop.EventLoopPolicy object at 0x7f77bb4cba50>
INFO:Controller:reorg limit is 8,000 blocks
INFO:Daemon:daemon #1 at host.testcontainers.internal:33941/ (current)
INFO:DB:switching current directory to /data
INFO:DB:using leveldb for DB backend
INFO:DB:created new database
INFO:DB:creating metadata directory
INFO:DB:UTXO DB version: 8
INFO:DB:coin: BitcoinSegwit
INFO:DB:network: regtest
INFO:DB:height: -1
INFO:DB:tip: 0000000000000000000000000000000000000000000000000000000000000000
INFO:DB:tx count: 0
INFO:DB:flushing DB cache at 1,200 MB
INFO:DB:sync time so far: 00s
INFO:History:history DB version: 1
INFO:History:flush count: 0
INFO:SessionManager:RPC server listening on 0.0.0.0:8000
INFO:Prefetcher:catching up to daemon height 0 (1 blocks behind)
INFO:Prefetcher:verified genesis block with hash 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206
INFO:BlockProcessor:our height: 0 daemon: 0 UTXOs 0MB hist 0MB
INFO:BlockProcessor:caught up to height 0
INFO:DB:flushed filesystem data in 0.00s
INFO:History:flushed history in 0.0s for 0 addrs
INFO:DB:flushed 1 blocks with 0 txs, 0 UTXO adds, 0 spends in 0.0s, committing...
INFO:DB:flush #1 took 0.0s.  Height 0 txs: 0 (+0)
INFO:DB:tx/sec since genesis: 0, since last flush: 1
INFO:DB:sync time: 00s  ETA: -1d 23h 59m
INFO:BlockProcessor:ElectrumX 1.16.0 synced to height 0
INFO:DB:closing DBs to re-open for serving
INFO:DB:opened UTXO DB (for sync: False)
INFO:DB:UTXO DB version: 8
INFO:DB:coin: BitcoinSegwit
INFO:DB:network: regtest
INFO:DB:height: 0
INFO:DB:tip: 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206
INFO:DB:tx count: 0
INFO:History:history DB version: 1
INFO:History:flush count: 1
INFO:DB:populating header merkle cache...
INFO:MemPool:beginning processing of daemon mempool.  This can take some time...
INFO:DB:header merkle cache populated in 0.0s
INFO:SessionManager:max session count: 250
INFO:SessionManager:session timeout: 600 seconds
INFO:SessionManager:session cost hard limit 10,000
INFO:SessionManager:session cost soft limit 1,000
INFO:SessionManager:bandwidth unit cost 5,000
INFO:SessionManager:request sleep 2,500ms
INFO:SessionManager:request timeout 30s
INFO:SessionManager:initial concurrent 10
INFO:SessionManager:max response size 1,000,000 bytes
INFO:MemPool:compact fee histogram: []
INFO:MemPool:synced in 0.01s
INFO:MemPool:0 txs 0.00 MB touching 0 addresses
INFO:SessionManager:TCP server listening on all_interfaces:50001
INFO:SessionManager:SSL server listening on all_interfaces:50002
INFO:SessionManager:WSS server listening on all_interfaces:50004
INFO:PeerManager:peer discovery: SELF
INFO:PeerManager:peer discovery is disabled
INFO:ElectrumX:[0] SSL 172.17.0.1:58178, 0 total
INFO:ElectrumX:[1] SSL 172.17.0.1:58182, 0 total
INFO:ElectrumX:[2] SSL 172.17.0.1:58202, 1 total
INFO:ElectrumX:[3] SSL 172.17.0.1:58208, 1 total
INFO:Prefetcher:new block height 11 hash 1d91ecb7327efc7cc30c3c9cd06b83239c699dce176ecc9a6b5998b850cd500b
INFO:DB:flush #2 took 0.0s.  Height 11 txs: 11 (+11)
INFO:BlockProcessor:processed 11 blocks size 0.00 MB in 0.0s
INFO:Prefetcher:new block height 102 hash 5ee8c86eb9f7fb351d3b97be1e2e7131b6d9387af12a33057507cebe12b95824
INFO:DB:flush #3 took 0.0s.  Height 102 txs: 102 (+91)
INFO:BlockProcessor:processed 91 blocks size 0.02 MB in 0.0s
DEBUG:MemPool:waiting for DB to sync
INFO:Prefetcher:new block height 107 hash 09e56ed052aa05f23887486e9004c9a37c0292d7e599eea3933830cc8d654488
INFO:DB:flush #4 took 0.0s.  Height 107 txs: 107 (+5)
INFO:BlockProcessor:processed 5 blocks size 0.00 MB in 0.0s
DEBUG:MemPool:waiting for DB to sync
INFO:Prefetcher:new block height 112 hash 34cd27e762b8aedda48bef0b61b2467004d70b31bcb6a54ddcc274559409bc1a
INFO:DB:flush #5 took 0.0s.  Height 112 txs: 112 (+5)
INFO:BlockProcessor:processed 5 blocks size 0.00 MB in 0.0s
DEBUG:MemPool:waiting for DB to sync
INFO:Prefetcher:new block height 118 hash 15771d82696f52009889057a149247a45b558369368adef96c9c9a8ef20e43fe
INFO:DB:flush #6 took 0.0s.  Height 118 txs: 118 (+6)
INFO:BlockProcessor:processed 6 blocks size 0.00 MB in 0.0s
INFO:ElectrumX:[1] notified of 1 address
INFO:ElectrumX:[1] sent tx: d658bc23ca3cb4b52838add51a5494d7e68973392994a1818450389d0f7e1105
INFO:Prefetcher:new block height 123 hash 1eecbc4f2930eb538317abdb5a03ac5f1e80ed41d38bf25e21e8f722ad558c1b
INFO:DB:flush #7 took 0.0s.  Height 123 txs: 124 (+6)
INFO:BlockProcessor:processed 5 blocks size 0.00 MB in 0.0s
INFO:ElectrumX:[3] notified of 1 address
INFO:ElectrumX:[1] notified of 1 address
INFO:ElectrumX:[1] sent tx: df4bb9ebea03f8a5218c26b06ed90217b0e386b009cf70800ad5f8648959d11a

Test ends successfully.

Logs from v1.18:

INFO:electrumx:ElectrumX server starting
INFO:electrumx:logging level: DEBUG
INFO:Controller:Python version: 3.13.5 (main, Jun 25 2025, 18:55:22) [GCC 14.2.0]
INFO:Controller:software version: ElectrumX 1.18.0
INFO:Controller:aiorpcX version: 0.25.0
INFO:Controller:supported protocol versions: 1.4-1.4.3
INFO:Controller:event loop policy: <uvloop.EventLoopPolicy object at 0x7fa8770fcd70>
INFO:Controller:reorg limit is 8,000 blocks
INFO:Daemon:daemon #1 at host.testcontainers.internal:33952/ (current)
INFO:DB:switching current directory to /data
INFO:DB:using leveldb for DB backend
INFO:DB:created new database
INFO:DB:creating metadata directory
INFO:DB:UTXO DB version: 8
INFO:DB:coin: Bitcoin
INFO:DB:network: regtest
INFO:DB:height: -1
INFO:DB:tip: 0000000000000000000000000000000000000000000000000000000000000000
INFO:DB:tx count: 0
INFO:DB:flushing DB cache at 1,200 MB
INFO:DB:sync time so far: 00s
INFO:History:history DB version: 1
INFO:History:flush count: 0
INFO:SessionManager:RPC server listening on 0.0.0.0:8000
INFO:Prefetcher:catching up to daemon height 0 (1 blocks behind)
INFO:Prefetcher:verified genesis block with hash 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206
INFO:BlockProcessor:our height: 0 daemon: 0 UTXOs 0MB hist 0MB
INFO:BlockProcessor:caught up to height 0
INFO:DB:flushed filesystem data in 0.00s
INFO:History:flushed history in 0.0s for 0 addrs
INFO:DB:flushed 1 blocks with 0 txs, 0 UTXO adds, 0 spends in 0.0s, committing...
INFO:DB:flush #1 took 0.0s.  Height 0 txs: 0 (+0)
INFO:DB:tx/sec since genesis: 0, since last flush: 1
INFO:DB:sync time: 00s  ETA: -1d 23h 59m
INFO:BlockProcessor:ElectrumX 1.18.0 synced to height 0
INFO:DB:closing DBs to re-open for serving
INFO:DB:opened UTXO DB (for sync: False)
INFO:DB:UTXO DB version: 8
INFO:DB:coin: Bitcoin
INFO:DB:network: regtest
INFO:DB:height: 0
INFO:DB:tip: 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206
INFO:DB:tx count: 0
INFO:History:history DB version: 1
INFO:History:flush count: 1
INFO:DB:populating header merkle cache...
INFO:MemPool:beginning processing of daemon mempool.  This can take some time...
INFO:DB:header merkle cache populated in 0.0s
INFO:SessionManager:max session count: 250
INFO:SessionManager:session timeout: 600 seconds
INFO:SessionManager:session cost hard limit 10,000
INFO:SessionManager:session cost soft limit 1,000
INFO:SessionManager:bandwidth unit cost 5,000
INFO:SessionManager:request sleep 2,500ms
INFO:SessionManager:request timeout 30s
INFO:SessionManager:initial concurrent 10
INFO:SessionManager:max response size 8,100,000 bytes
INFO:MemPool:compact fee histogram: []
INFO:MemPool:synced in 0.01s
INFO:MemPool:0 txs 0.00 MB touching 0 addresses
INFO:SessionManager:TCP server listening on all_interfaces:50001
INFO:SessionManager:SSL server listening on all_interfaces:50002
INFO:SessionManager:WSS server listening on all_interfaces:50004
INFO:PeerManager:peer discovery: SELF
INFO:PeerManager:peer discovery is disabled
INFO:ElectrumX:[0] SSL 172.17.0.1:42072, 0 total
DEBUG:ElectrumX:[0] starting taskgroup.
DEBUG:ElectrumX:[0] taskgroup stopped.
INFO:ElectrumX:[1] SSL 172.17.0.1:42082, 0 total
DEBUG:ElectrumX:[1] starting taskgroup.
INFO:ElectrumX:[2] SSL 172.17.0.1:49730, 1 total
DEBUG:ElectrumX:[2] starting taskgroup.
DEBUG:ElectrumX:[2] taskgroup stopped.
INFO:ElectrumX:[3] SSL 172.17.0.1:49744, 1 total
DEBUG:ElectrumX:[3] starting taskgroup.
DEBUG:MemPool:waiting for DB to sync
INFO:Prefetcher:new block height 11 hash 2c2a7ac45df43cbd2ec704e615e510ed809bdc967724b02db559e1817cf06d04
INFO:Prefetcher:new block height 103 hash 498f6d2bd203bf7c02c6ee616ab33ac8a33f2cbae298a1b9ebb3731caf6471b2
INFO:DB:flush #2 took 0.0s.  Height 11 txs: 11 (+11)
INFO:BlockProcessor:processed 11 blocks size 0.00 MB in 0.0s
INFO:DB:flush #3 took 0.0s.  Height 103 txs: 103 (+92)
INFO:BlockProcessor:processed 92 blocks size 0.02 MB in 0.0s
DEBUG:MemPool:waiting for DB to sync
INFO:Prefetcher:new block height 108 hash 22fb4c0c947551d46795d59e419810e24560b00e9ae024950ecab7b78ea86f06
INFO:DB:flush #4 took 0.0s.  Height 108 txs: 108 (+5)
INFO:BlockProcessor:processed 5 blocks size 0.00 MB in 0.0s
DEBUG:MemPool:waiting for DB to sync
INFO:Prefetcher:new block height 113 hash 7292cebee13c68532a1ee7324e4c1d98994653bb032380eadc7c4cfdfac3f3b5
INFO:DB:flush #5 took 0.0s.  Height 113 txs: 113 (+5)
INFO:BlockProcessor:processed 5 blocks size 0.00 MB in 0.0s
DEBUG:MemPool:waiting for DB to sync
INFO:Prefetcher:new block height 118 hash 4ab0ab023ad47ca3e12f4b20aa176ab8bc8dd4ab825b6e1d050ca18f4c3a6927
INFO:DB:flush #6 took 0.0s.  Height 118 txs: 118 (+5)
INFO:BlockProcessor:processed 5 blocks size 0.00 MB in 0.0s
DEBUG:MemPool:waiting for DB to sync
INFO:Prefetcher:new block height 123 hash 39886275c6597c782b845892c6567cfa9cf77522d2dc1b93118ed12e3f9c379c
INFO:DB:flush #7 took 0.0s.  Height 123 txs: 123 (+5)
INFO:BlockProcessor:processed 5 blocks size 0.00 MB in 0.0s
DEBUG:MemPool:waiting for DB to sync
INFO:Prefetcher:new block height 128 hash 335d135e07987a1992f4f3955b2ea20ce277a2ae7f74fce1aa1a236655ee7ffb
INFO:DB:flush #8 took 0.0s.  Height 128 txs: 128 (+5)
INFO:BlockProcessor:processed 5 blocks size 0.00 MB in 0.0s
DEBUG:MemPool:waiting for DB to sync
INFO:Prefetcher:new block height 133 hash 473fa629b22ace5f769ead5742c67cfa7879de8133b28f115adbd45e856a5e8b
INFO:DB:flush #9 took 0.0s.  Height 133 txs: 133 (+5)
INFO:BlockProcessor:processed 5 blocks size 0.00 MB in 0.0s
DEBUG:MemPool:waiting for DB to sync
INFO:Prefetcher:new block height 138 hash 1b617be0d8d7fbda1d135355dbc477afc838c5c18e61b21c13c801d1bff60f3b
INFO:DB:flush #10 took 0.0s.  Height 138 txs: 138 (+5)
INFO:BlockProcessor:processed 5 blocks size 0.00 MB in 0.0s
DEBUG:MemPool:waiting for DB to sync
INFO:Prefetcher:new block height 143 hash 631c5e5abf0b9103a8705ca5f57b16c52d9e1735e964b793d1fb406aa4312cdf
INFO:DB:flush #11 took 0.0s.  Height 143 txs: 143 (+5)
INFO:BlockProcessor:processed 5 blocks size 0.00 MB in 0.0s
DEBUG:MemPool:waiting for DB to sync
INFO:Prefetcher:new block height 148 hash 3db51d317fec590a236968658726894c32fd70794b32451d8be6413789882789
INFO:DB:flush #12 took 0.0s.  Height 148 txs: 148 (+5)
INFO:BlockProcessor:processed 5 blocks size 0.00 MB in 0.0s
DEBUG:MemPool:waiting for DB to sync
INFO:Prefetcher:new block height 153 hash 28c964259d14e57ef2541a403dfdad20c68dd15641b94eacb15624a0c9168e9d
INFO:DB:flush #13 took 0.0s.  Height 153 txs: 153 (+5)
INFO:BlockProcessor:processed 5 blocks size 0.00 MB in 0.0s
DEBUG:MemPool:waiting for DB to sync
INFO:Prefetcher:new block height 158 hash 67e9f45e4a95b1227e3ca06e4c5e9b77c69baeecab39cef5c4481e6357225305
INFO:DB:flush #14 took 0.0s.  Height 158 txs: 158 (+5)
INFO:BlockProcessor:processed 5 blocks size 0.00 MB in 0.0s
DEBUG:MemPool:waiting for DB to sync
INFO:Prefetcher:new block height 163 hash 26d356a35771090872b86926621e4b7d05ea827afcb3b3a8eaf0c22fef7cba1e
INFO:DB:flush #15 took 0.0s.  Height 163 txs: 163 (+5)
INFO:BlockProcessor:processed 5 blocks size 0.00 MB in 0.0s
DEBUG:MemPool:waiting for DB to sync
INFO:Prefetcher:new block height 168 hash 0323972ceb2378664cf4014cc7bebd5ba4a23ccedd42d5b65358b78ed36f0437
INFO:DB:flush #16 took 0.0s.  Height 168 txs: 168 (+5)
INFO:BlockProcessor:processed 5 blocks size 0.00 MB in 0.0s

Test times out after a certain period of time.

theborakompanioni avatar Sep 14 '25 12:09 theborakompanioni

Do you have code or instructions you can share that reproduces the issue?

If you can reliably reproduce, try to bisect the commits, to find the exact commit that introduces the change.

Based on your logs, you updated from python 3.7 to 3.13 at the same time. I imagine you also updated a lot of other deps. Try updating fewer things at a time, to pinpoint the cause.

SomberNight avatar Sep 15 '25 02:09 SomberNight

Thank you @SomberNight 🙏

Do you have code or instructions you can share that reproduces the issue?

Yeah, test in question can be seen at in ElectrumGatewayExampleApplicationTest#verifyTargetWalletReceivesCoins. However, I expect it is quite cumbersome to comprehend if you are not into it. As mentioned above, it basically tries to "regularly mine block rewards to an address; on maturity, send them to a different wallet and verify the incoming tx".

If you can reliably reproduce, try to bisect the commits, to find the exact commit that introduces the change.

Based on your logs, you updated from python 3.7 to 3.13 at the same time. I imagine you also updated a lot of other deps. Try updating fewer things at a time, to pinpoint the cause.

I am using lukechilds docker container images and upgraded from lukechilds/electrumx:v1.16.0 to lukechilds/electrumx:v1.18.0. Thought you might have an idea before trying to bisect. Currently reverted to v1.16.0, but I will report back on the next upgrade attempt.

theborakompanioni avatar Oct 21 '25 17:10 theborakompanioni