V5.2.0 : UpdateWitnessHeights : Assertion `nd.witnessHeight == -1' failed

ChileBob · August 2, 2022, 10:32pm

Attempting to sync backup node, it seems to be borked after upgrade.

zcashd: wallet/wallet.cpp:2655: void UpdateWitnessHeights(NoteDataMap &, int, int64_t) [NoteDataMap = std::map<SaplingOutPoint, SaplingNoteData>]: Assertion `nd.witnessHeight == -1’ failed.

mdr0id · August 2, 2022, 11:07pm

ACK. I have reproduced this also locally from a v5.1.0 to v5.2.0. There are some issues on github related to this:

github.com/zcash/zcash

Zcashd v5.2.0 crashes

opened 09:15PM - 27 Jul 22 UTC

PRabahy

### Describe the issue I upgraded from ZecWallet from 1.8.1 (never seemed to fi…nish catching up) to 1.8.2 and now I am getting the following message. I posted a bug report to their github tracker (https://github.com/ZcashFoundation/zecwallet/issues/375) and @adityapk00 said I should post it here. ### Can you reliably reproduce the issue? No ### Actual behaviour + errors ``` 2022-07-27T02:57:45.097068Z INFO main: UpdateTip: new best hash=0000000001d089c19d9c21b78bc09006cc3f33341a2c5f4447a88c534a57d0ea height=1737754 bits=469904555 log2_work=59.292453 tx=11100880 date=2022-07-14 22:55:18 progress=0.991649 cache=17.3MiB(3156tx) 2022-07-27T02:57:48.760742Z INFO ProcessNewBlock: main: UpdateTip: new best hash=0000000000fb6d5abdb000e6f67d70ec08abbc085d09185d0396de614646a22f height=1737755 bits=469906136 log2_work=59.292454 tx=11100902 date=2022-07-14 22:55:52 progress=0.991649 cache=17.3MiB(3160tx) 2022-07-27T02:57:49.415616Z INFO ProcessNewBlock: main: UpdateTip: new best hash=0000000000779980ae22457330e8117704ee89f523f0f5a0d1f06f105f8982c0 height=1737756 bits=469903792 log2_work=59.292455 tx=11100903 date=2022-07-14 22:57:44 progress=0.991650 cache=17.3MiB(3161tx) 2022-07-27T02:57:49.747723Z INFO ProcessNewBlock: main: Pre-allocating up to position 0x7000000 in blk00344.dat 2022-07-27T02:57:52.945802Z INFO ProcessNewBlock: main: UpdateTip: new best hash=0000000000044037130f6a7cd672b30058c529f96b8949c358273e68d0931a82 height=1737757 bits=469908720 log2_work=59.292456 tx=11100923 date=2022-07-14 22:58:01 progress=0.991650 cache=17.3MiB(3164tx) 2022-07-27T02:57:56.414568Z INFO ProcessNewBlock: main: UpdateTip: new best hash=00000000007e9319bbdfdebca0ccbe4ed7226aa3d77719352ffcd7878d9aeb97 height=1737758 bits=469906698 log2_work=59.292457 tx=11100929 date=2022-07-14 22:58:26 progress=0.991651 cache=17.3MiB(3165tx) 2022-07-27T02:57:57.089757Z INFO ProcessNewBlock: main: Pre-allocating up to position 0x8000000 in blk00344.dat 2022-07-27T02:57:57.301610Z ERROR main: ReadBlockFromDisk(CBlock&, CBlockIndex*): block index entry does not provide a valid disk position for block CBlockIndex(pprev=000001805e87aaa0, nHeight=1737786, merkle=a0efc7a977b90a6bb54ccf88ec5582996393907cd8238d13df4ea7a89a213fcb, hashBlock=00000000026995e1e3d30af4e5acb2af3f54ff6b76230679528eb3a2d65c4ea3) at CBlockDiskPos(nFile=-1, nPos=0) 2022-07-27T02:57:57.301631Z INFO main: *** ThreadNotifyWallets: Failed to read block 00000000026995e1e3d30af4e5acb2af3f54ff6b76230679528eb3a2d65c4ea3 while collecting shielded outputs 2022-07-27T02:57:57.301638Z INFO main: Error: Error: A fatal internal error occurred, see debug.log for details 2022-07-27T02:57:57.302113Z INFO main: txnotify thread exit 2022-07-27T02:57:57.315099Z INFO main: tor: Thread interrupt 2022-07-27T02:57:57.315281Z INFO main: torcontrol thread exit 2022-07-27T02:57:57.315375Z INFO main: addcon thread interrupt 2022-07-27T02:57:57.315375Z INFO main: opencon thread interrupt 2022-07-27T02:57:57.315459Z INFO main: scheduler thread interrupt 2022-07-27T02:57:57.346894Z INFO main: net thread interrupt 2022-07-27T02:57:57.428511Z INFO ProcessNewBlock: main: UpdateTip: new best hash=00000000008bce2ea6f102f3a46d2c39250c087e6c188d9db035793187b40dcd height=1737759 bits=469905061 log2_work=59.292458 tx=11100937 date=2022-07-14 23:04:01 progress=0.991653 cache=17.3MiB(3173tx) 2022-07-27T02:57:57.428671Z INFO main: msghand thread interrupt 2022-07-27T02:57:57.428840Z INFO Shutdown: main: StopRPC: waiting for async rpc workers to stop 2022-07-27T02:57:57.603469Z INFO Shutdown: main: StopNode() 2022-07-27T02:57:58.072444Z INFO Shutdown: main: done 2022-07-27T03:00:55.386494Z INFO main: ``` ### The version of Zcash you were using: Zcash Daemon version v5.2.0 ### Machine specs: - OS name + version: Windows 10 Home 21H2 - CPU: AMD Ryzen 5 2600 Six-Core Processor 3.40 GHz - RAM: 16.0 GB - Disk size: 2TB - Disk Type (HD/SDD): SATA SSD - Linux kernel version (uname -a): n/a - Compiler version (gcc --version): unknown - Whatever https://github.com/ZcashFoundation/zecwallet uses - Linker version (ld -v): unknown - Whatever https://github.com/ZcashFoundation/zecwallet uses - Assembler version (as --version): unknown - Whatever https://github.com/ZcashFoundation/zecwallet uses ### Do you have a backup of `~/.zcash` directory and/or take a VM snapshot? I can if you need it, but I think the log posted is the most relevant thing.

github.com/zcash/zcash

zcashd: Assertion 'nd->witnessHeight == -1'

opened 04:12PM - 21 Jul 22 UTC

LarryRuane

C-bug A-wallet

I copied most of the following from slack: I started `zcashd` that I built at… master branch commit 3213527141782a9a4e018e00d34de16889a128f0, which is about a week newer than v5.1.0, and a soon after startup: ``` zcashd: wallet/wallet.cpp:2662: void UpdateWitnessHeights(NoteDataMap &, int, int64_t) [NoteDataMap = std::map<JSOutPoint, SproutNoteData>]: Assertion `nd->witnessHeight == -1' failed. Aborted (core dumped) ``` Here are the last few lines of `debug.log`: ``` 2022-07-17T17:59:36.855409Z INFO Init: main: init message: Loading wallet... 2022-07-17T17:59:38.080864Z INFO Init: main: nFileVersion = 5010050 2022-07-17T17:59:38.086936Z INFO Init: main: Keys: 524 plaintext, 0 encrypted, 524 w/ metadata, 524 total 2022-07-17T17:59:38.086958Z INFO Init: main: ZKeys: 4 plaintext, 0 encrypted, 4 w/metadata, 4 total 2022-07-17T17:59:38.090910Z INFO Init: main: wallet 1235ms 2022-07-17T17:59:38.091662Z INFO Init: main: init message: Rescanning... 2022-07-17T17:59:38.091683Z INFO Init: main: CWallet::InitLoadWallet(): Rescanning last 3 blocks (from block 1740905)... 2022-07-17T17:59:38.091696Z INFO Init: main: CWallet::ScanForWalletTransactions(): Rewinding Orchard wallet to height 1740904; current is 1740905 ``` My datadir, in particular my wallet, may have been corrupted because I'm always running various non-release versions and testing different things, but I have no reason to think there may have been any corruption (the last time I interacted with this data directory, everything was normal). I restarted the node, and the assertion repeated. Then I reverted back to v5.1.0 and restarted `zcashd`, and it seemed to rescan the entire blockchain: ``` 2022-07-18T04:33:43.461421Z INFO Init: main: CWallet::InitLoadWallet(): Rescanning last 1740908 blocks (from block 0)... 2022-07-18T04:34:43.025799Z INFO Init: main: Still rescanning. At block 325479. Progress=0.089687 ``` Then many "Still rescanning" log lines , one per minute... then: ``` 2022-07-18T10:11:20.196343Z INFO Init: main: Still rescanning. At block 1740762. Progress=0.999416 2022-07-18T10:12:21.020107Z INFO Init: main: Still rescanning. At block 1740890. Progress=0.999488 2022-07-18T10:12:35.259690Z INFO Init: main: rescan 20331792ms ``` and then startup continued normally. That's about 5.6 hours of rescan time. Then, on str4d's suggestion, I moved back to 3213527141782a9a4e018e00d34de16889a128f0 and started again, and the problem reproduced in the same way, so apparently the full rescan didn't repair the datadir. I uploaded the data directory to [ECC google drive](https://drive.google.com/file/d/1djVML9zw0joyMVWOgmlfIIM2GG0ML3Tg/view?usp=sharing) (compressed tar). The problem should be reproducible with that datadir. Other possibly useful details: _After_ copying the datadir, I restarted back on v5.1.0, and this time it rescanned only 34 blocks (rather than the entire history as it had done last time): ``` 2022-07-19T05:04:03.236046Z INFO Init: main: ZKeys: 4 plaintext, 0 encrypted, 4 w/metadata, 4 total 2022-07-19T05:04:03.237027Z INFO Init: main: wallet 745ms 2022-07-19T05:04:03.237126Z INFO Init: main: CWallet::InitLoadWallet(): Rescanning last 34 blocks (from block 1741978)... 2022-07-19T05:04:03.237153Z INFO Init: main: CWallet::ScanForWalletTransactions(): Rewinding Orchard wallet to height 1741977; current is 1741978 2022-07-19T05:04:21.570236Z INFO Init: main: rescan 18333ms 2022-07-19T05:04:21.630772Z INFO main: txnotify thread start ``` and it didn't crash, synced normally. But after syncing, the private balance is way off, I'm very sure that wallet doesn't have this much ZEC, it has only a small fraction of both transparent and shielded that I keep around for testing. The transparent balance looks correct (IIRC), and the private was similar. ``` $ src/zcash-cli z_gettotalbalance { "transparent": "0.0311", "private": "775.12730662", "total": "775.15840662" } ``` I'm aware that this RPC is deprecated, but it shouldn't produce wrong results. My platform is Ubuntu 22.04 on intel (it's actually a virtualbox VM guest within a windows 10 host, running on a Dell laptop).

What config are you using?

Specifically. are you using txindex insightexplorer or lwd flags in zcash.conf?

ChileBob · August 3, 2022, 12:12am

zcash.conf is pure vanilla :-

mainnet=1
addnode=mainnet.z.cash
rpcuser=deleted
rpcpassword=deleted
rpcport=8232

EDIT: Attempting to recover with ‘-reindex’