assertion failed: Mutator set in wallet-handler must agree with that from applied block

[dan-da]

I am encountering an assertion failure which causes neptune-core to exit.

I see this issue when I run 3 regtest nodes via ./scripts/linux/run-multiple-instances-from-genesis.sh.

I've seen it the last 3 times I've run the script. It has occurred between block height 17 and 22. Thus, it seems to be repeatable, but presently it takes 2+ hours to reproduce, and the cause is unknown to me.

Context: For this run, the assertion failure occurs after we have received a new block with height 17 from a peer, and for some reason we do not find the parent block 16, so we request it from peer successfully, validate both 16 and 17, and then we run into problems when adding 16 to the mutator set. First we get a warning about invalid membership proof, and then the failed assertion.

2024-05-02T21:33:25.458522345Z  WARN ThreadId(01) neptune_core::models::state::wallet::wallet_state: Unable to find valid membership proof for UTXO with digest 12872966500503771395,08720121959710473260,15098414805492485189,08922435677617307160,08704379632733764168. UTXO was received at block height 16. Current block height is 16
2024-05-02T21:33:25.458890332Z DEBUG ThreadId(01) neptune_core::models::state::wallet::wallet_state: Block has 0 removal records
2024-05-02T21:33:25.458918024Z DEBUG ThreadId(01) neptune_core::models::state::wallet::wallet_state: Transaction has 0 inputs
thread 'main' panicked at /home/danda/dev/neptune/neptune-core/src/models/state/wallet/wallet_state.rs:557:9:
assertion `left == right` failed: Mutator set in wallet-handler must agree with that from applied block
  left: Digest([BFieldElement(4514042713164102574), BFieldElement(15081518964394651370), BFieldElement(11011453280472744399), BFieldElement(7264123475751919451), BFieldElement(6231984811448752325)])
 right: Digest([BFieldElement(15627704739818148120), BFieldElement(8508543671595713473), BFieldElement(9227237851504558526), BFieldElement(13522751993922005009), BFieldElement(3523287006231399016)])

It seems odd to me that we did not already have block 16 present. Looking in the logs of the peer that mined blocks 16,17 I see that they have the same timestamp (at least to the same second). Here is block 16:

2024-05-02T21:31:32.901142679Z DEBUG ThreadId(01) neptune_core::models::state::archival_state: Updating mutator set: adding block with height 16.  Mined: Thu, 2 May 2024 14:31:32 -0700

However, block 17 clearly was mined almost 2 minutes later, as we see from this log message:

2024-05-02T21:33:25.328407763Z DEBUG ThreadId(01) neptune_core::models::state::archival_state: Updating mutator set: adding block with height 17.  Mined: Thu, 2 May 2024 14:31:32 -0700

notice the log entry time is 21:33:25 while the block timestamp is 14:31:32. (latter is displayed with localtime offset)

So I find that suspicious and worth investigation, whether its the cause or not.

Looking at the mining loop code, I notice that we change the nonce each iteration but we do not change the timestamp. So the timestamp will reflect when we started mining on that block rather than when the winning block digest was found. Which is not what most people would expect, eg when looking at a block explorer. My understanding is that bitcoin miners by convention change the timestamp at least once per second while mining, though it is not required by consensus rules.

I will evaluate changing the mining loop to also update the timestamp. Though I don't believe that will fix this issue.

edit: The fixed timestamp appears intentional as the difficulty is based on the timestamp and block validity checks ensure they match. So changing the timestamp would require changing difficulty as well. I won't make any change without further discussion.

Anyway, here is a more complete log.

log.txt

[Sword-Smith]

I'm trying to tackle this problem. The issue is that the value previous_ms_accumulator that is passed to WalletState::update_wallet_state_with_new_block is incorrect whenever there is a fork.