spesmilo / electrumx

Alternative implementation of spesmilo/electrum-server
MIT License
432 stars 343 forks source link

ZEC electrum crashes with AssertionError after ZEC hardfork was activated #181

Open cipig opened 2 years ago

cipig commented 2 years ago

this is the error

May 31 17:48:10 electrum1 electrumx_server[1507364]: INFO:Prefetcher:new block height 1,687,103 hash 000000000162bdf56998ca7703adad22cdce21252f6354c077e82ccf434e761f
May 31 17:48:10 electrum1 electrumx_server[1507364]: INFO:DB:flush #338 took 0.0s.  Height 1,687,103 txs: 10,569,143 (+1)
May 31 17:48:10 electrum1 electrumx_server[1507364]: INFO:BlockProcessor:processed 1 block size 0.00 MB in 0.0s
May 31 17:48:37 electrum1 electrumx_server[1507364]: INFO:MemPool:0 txs 0.00 MB touching 0 addresses
May 31 17:48:47 electrum1 electrumx_server[1507364]: INFO:ElectrumX:[261] TCP 88.155.42.59:58420, 44 total
May 31 17:49:29 electrum1 electrumx_server[1507364]: INFO:ElectrumX:[262] TCP 91.232.29.13:52390, 44 total
May 31 17:49:37 electrum1 electrumx_server[1507364]: INFO:MemPool:0 txs 0.00 MB touching 0 addresses
May 31 17:50:07 electrum1 electrumx_server[1507364]: INFO:Prefetcher:cancelled; prefetcher stopping
May 31 17:50:07 electrum1 electrumx_server[1507364]: INFO:BlockProcessor:flushing to DB for a clean shutdown...
May 31 17:50:07 electrum1 electrumx_server[1507364]: INFO:SessionManager:closing down server for ssl://all_interfaces:20058
May 31 17:50:07 electrum1 electrumx_server[1507364]: INFO:SessionManager:closing down server for tcp://all_interfaces:10058
May 31 17:50:07 electrum1 electrumx_server[1507364]: INFO:SessionManager:closing down server for rpc://localhost:8058
May 31 17:50:07 electrum1 electrumx_server[1507364]: INFO:SessionManager:closing down server for wss://all_interfaces:30058
May 31 17:50:08 electrum1 electrumx_server[1507364]: INFO:Controller:shutting down
May 31 17:50:08 electrum1 electrumx_server[1507364]: INFO:Controller:shutdown complete
May 31 17:50:08 electrum1 electrumx_server[1507364]: ERROR:electrumx:ElectrumX server terminated abnormally
May 31 17:50:08 electrum1 electrumx_server[1507364]: Traceback (most recent call last):
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/bin/electrumx_server", line 35, in main
May 31 17:50:08 electrum1 electrumx_server[1507364]:     asyncio.run(controller.run())
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/lib/python3.9/asyncio/runners.py", line 44, in run
May 31 17:50:08 electrum1 electrumx_server[1507364]:     return loop.run_until_complete(main)
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "uvloop/loop.pyx", line 1501, in uvloop.loop.Loop.run_until_complete
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/electrumx/lib/server_base.py", line 129, in run
May 31 17:50:08 electrum1 electrumx_server[1507364]:     await server_task
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/electrumx/lib/server_base.py", line 102, in serve
May 31 17:50:08 electrum1 electrumx_server[1507364]:     await self.serve(shutdown_event)
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/electrumx/server/controller.py", line 134, in serve
May 31 17:50:08 electrum1 electrumx_server[1507364]:     await group.spawn(wait_for_catchup())
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/aiorpcx/curio.py", line 297, in __aexit__
May 31 17:50:08 electrum1 electrumx_server[1507364]:     await self.join()
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/electrumx/lib/util.py", line 370, in join
May 31 17:50:08 electrum1 electrumx_server[1507364]:     task.result()
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/electrumx/server/mempool.py", line 368, in keep_synchronized
May 31 17:50:08 electrum1 electrumx_server[1507364]:     await group.spawn(self._logging(synchronized_event))
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/aiorpcx/curio.py", line 297, in __aexit__
May 31 17:50:08 electrum1 electrumx_server[1507364]:     await self.join()
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/electrumx/lib/util.py", line 370, in join
May 31 17:50:08 electrum1 electrumx_server[1507364]:     task.result()
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/electrumx/server/mempool.py", line 257, in _refresh_hashes
May 31 17:50:08 electrum1 electrumx_server[1507364]:     await self._process_mempool(hashes, touched, height)
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/electrumx/server/mempool.py", line 301, in _process_mempool
May 31 17:50:08 electrum1 electrumx_server[1507364]:     deferred, unspent = task.result()
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/electrumx/server/mempool.py", line 344, in _fetch_and_accept
May 31 17:50:08 electrum1 electrumx_server[1507364]:     tx_map = await run_in_thread(deserialize_txs)
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/aiorpcx/curio.py", line 57, in run_in_thread
May 31 17:50:08 electrum1 electrumx_server[1507364]:     return await get_event_loop().run_in_executor(None, func, *args)
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/lib/python3.9/concurrent/futures/thread.py", line 52, in run
May 31 17:50:08 electrum1 electrumx_server[1507364]:     result = self.fn(*self.args, **self.kwargs)
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/electrumx/server/mempool.py", line 331, in deserialize_txs
May 31 17:50:08 electrum1 electrumx_server[1507364]:     tx, tx_size = deserializer(raw_tx).read_tx_and_vsize()
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/electrumx/lib/tx.py", line 146, in read_tx_and_vsize
May 31 17:50:08 electrum1 electrumx_server[1507364]:     return self.read_tx(), self.binary_length
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/electrumx/lib/tx.py", line 388, in read_tx
May 31 17:50:08 electrum1 electrumx_server[1507364]:     self._read_inputs(),    # inputs
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/electrumx/lib/tx.py", line 156, in _read_inputs
May 31 17:50:08 electrum1 electrumx_server[1507364]:     return [read_input() for i in range(self._read_varint())]
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/electrumx/lib/tx.py", line 156, in <listcomp>
May 31 17:50:08 electrum1 electrumx_server[1507364]:     return [read_input() for i in range(self._read_varint())]
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/electrumx/lib/tx.py", line 162, in _read_input
May 31 17:50:08 electrum1 electrumx_server[1507364]:     self._read_varbytes(),   # script
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/electrumx/lib/tx.py", line 188, in _read_varbytes
May 31 17:50:08 electrum1 electrumx_server[1507364]:     return self._read_nbytes(self._read_varint())
May 31 17:50:08 electrum1 electrumx_server[1507364]:   File "/usr/local/lib/python3.9/dist-packages/electrumx/lib/tx.py", line 184, in _read_nbytes
May 31 17:50:08 electrum1 electrumx_server[1507364]:     assert self.binary_length >= end
May 31 17:50:08 electrum1 electrumx_server[1507364]: AssertionError

same error after restart, the last block that worked was INFO:DB:height: 1,687,103

hardfork was Activated at block 1687104, mined May 31, 2022 18:12 UTC+00:00 as of https://z.cash/upgrade/nu5/

APaddy commented 2 years ago

Exact same behavior on our end as well. Any ideas/solutions ?

cipig commented 2 years ago

not a dev, but i guess the deserializer for Zcash https://github.com/spesmilo/electrumx/blob/master/electrumx/lib/tx.py#L373 needs some changes because of the new v5 txes

chappjc commented 2 years ago

Someone I work with just updated our project for v5 ZEC txns. This might be informative: https://github.com/decred/dcrdex/blob/15df5a56d2e24e0e8fc211e70e5c45cb16a973b2/dex/networks/zec/tx.go#L467 (see the ZecDecode method).

BTW, is there an Electrum wallet fork for ZEC (that is production ready)? I've seen https://github.com/zebra-lucky/electrum-zcash, but it has zero stars and I cannot tell if it's official and/or trusted in the Zcash community.

cipig commented 2 years ago

BTW, is there an Electrum wallet fork for ZEC (that is production ready)? I've seen https://github.com/zebra-lucky/electrum-zcash, but it has zero stars and I cannot tell if it's official and/or trusted in the Zcash community.

use https://github.com/KomodoPlatform/atomicDEX-Desktop ... it's a wallet... and a DEX

smk762 commented 2 years ago

Nu5 transaction spec is in section 7.1 here - https://zips.z.cash/protocol/protocol.pdf

Seems the lock_time and nExpiryHeight have moved to earlier in the sequence, after a new addition, nConsensusBranchId

Comparison of two simple transactions:

v4 - https://zecblockexplorer.com/tx/29e854b05b0210cc86c7976c8f867c5034fb9ba1d1af37ae1437309a6b6e5a99

04000080         (v4 overwintered)
85202f89         (version group id)
01               (tx_in count)
979b6eaef699f5959dd21cad76fb7dfc4114f081afde32745e521da07d288d90 (vin_txid)
00000000         (vin_utxo_pos)
6a               (scriptSig byte length)
# Vin SIG
47304402200ca68cda4f783d8e78e3da129cd6a46ee4471e3fa711f9b90b1e9c847fdc21d5022072036a3ae187315c0d48ec7e88db263b865c3d7307780b262c2d4c278872762c0121035556ffd87eda7df56cf4a1f180022e22572920d70994cb9139ba973f2a105d71
ffffffff         (sequence)
01               (num outputs)
fdc4071c00000000 (output value)
19               (scriptpubkey byte length)
# scriptPubKey
76a91418ae4e28f414a29a171a922cae6fe4cad6370b3388ac
00000000         (lock_time)
cadf1800         (nExpiryHeight)
00000000
00000000
000000

v5 - https://zecblockexplorer.com/tx/56e806faf4f65661fd2c9294ca3fbc65bc24eb102722a2a21c290ac2dc67b11f

05000080         (v5 overwintered)
0a27a726         (version group id)
b4d0d6c2         (nConsensusBranchId)
f7c91900         (lock_time)
2aca1900         (nExpiryHeight)
01               (tx_in count)
e1a049c2fb3857b9f7198d3bee0d89f55c0f6c58452d59a5b90f016a28f71fd4 (vin_txid)
01000000         (vin_utxo_pos)
6a               (scriptSig byte length)
# Vin scriptSig Hex
4730440220255df3de1aa8039f8f0a2540e5b0a5fa1f6dca956fd3950c1db9ba201d94721c02200325cd66a7de814668409c79e25cb6b29a1256842f16be91c079ff02ad888e330121022c6e35dc470bdb9e80a99ec8ce2738386cc580236c34819f9dcdcf9435e01819
feffffff         (sequence)
02               (num outputs)
6d68cf0c00000000 (214919277 sat output)
19               (scriptpubkey byte length)
# scriptPubKey
76a9144fd8aa604033240ad3efb8c8cfc8fe5a5d1f0a8288ac
9af71b0a03000000 (13054506906 sat output)
19               (25 bytes for scriptpubkey)
# scriptPubKey
76a91405b8cbd7b6ef547ad44172be8e3bfcb5ae77779b88ac
000000

It can get a little more complicated for orchard transactions etc.

str4d commented 2 years ago

Hi! zcashd developer here; I've just been pointed to this issue.

Everything that was deployed in NU5 is documented in ZIP 252. You should check there to see what changes need to be made to ElectrumX to be NU5 compatible (in particular, note that if ElectrumX tries to speak the Zcash P2P network protocol, it needs to be made compatible with ZIP 239; I don't know anything about ElectrumX so can't say if this is relevant).

You've found the right part of the protocol spec for the v5 transaction format. It's also specified in ZIP 225.

v5 transactions use a new txid calculation that is non-malleable, and a corresponding new signature digest algorithm. These are specified in ZIP 244.

If you need reference code, we have the above two ZIPs implemented in Python as part of our structural test vector generator:

DeckerSU commented 1 year ago

Almost done the fix: image As you are see ZCash node is fully synchronized and ElectrumX successfully passed NU5 activation height 1687104. Implementation of txid calculation was directly taken from zcash test_framework as it have all needed (de)ser procs and txid_digest calc method. Also fixed small error in sapling_spends_noncompact_digest which leads to Python exception on certain transactions:

AttributeError: 'SpendDescriptionV5' object has no attribute 'anchor'

like ca6abd8ef7d6ef158a4a35ea2c2c0cf122f2f664a88f8fa5b6fd79e48c5bed59.

Need to polish few moments and will publish a draft of sources. Also will make a PR into zcash repo with fixed error in test_framework.

DeckerSU commented 1 year ago

@cipig can you try the implementation from my patch-issue-181 branch?

2All: patch-issue-181 is a working ElectrumX solution for ZEC at present. I tested it in my testlab - everything seems Ok.

cipig commented 1 year ago

implementation works fine, electrumx server syncs and i also used that electrum for some swaps on AtomicDEX, so all good thanks a lot

cipig commented 1 year ago

@DeckerSU can you please do a PR with your changes? Or is there something missing?