bug: hash mismatch happens sometimes during bootstrapping

[rkuris]

I think this is a separate bug from the memory growth issue, so I'm creating a new one.

[rkuris]

Known failing blocks and their source:

Antithesis:

• 266
• 308
• 326
• 21109
• 29830
• 34497
• 34502
• 34505

Aaron's runs:

• 308 (dup from Antethesis)
• 34497 (dup from Antethesis)
• 27881 (unique)

Rodrigo:

• 308 (dup from Antithesis + Aaron)
• 21109 (dup from Antithesis)
• 34502 (dup from Antithesis)
• 2519497
• 2532403 :/

[aaronbuchwald]

ref ava-labs/avalanchego#4598

[aaronbuchwald]

Merged support for re-execution w/ firewood on August 26th here: ava-labs/avalanchego#4180
Reported the issue as the flake started showing up non-deterministically in CI immediately after on August 27th: ava-labs/avalanchego#4598
Removed from CI on August 28th: ava-labs/avalanchego#4227

[aaronbuchwald]

Within a single failure case here: https://github.com/ava-labs/avalanchego/actions/runs/19315010303/job/55244272668?pr=4505#step:4:4019

The key-value set from the first attempt to create a proposal on the parent is here:

https://github.com/ava-labs/avalanchego/actions/runs/19315010303/job/55244272668?pr=4505#step:4:4019

The key-value set when we attempt to verify a proposal on top of the same root is different:

https://github.com/ava-labs/avalanchego/actions/runs/19315010303/job/55244272668?pr=4505#step:4:4027

[aaronbuchwald]

Within a single failure case here: https://github.com/ava-labs/avalanchego/actions/runs/19315010303/job/55244272668?pr=4505#step:4:4019

The key-value set from the first attempt to create a proposal on the parent is here:

https://github.com/ava-labs/avalanchego/actions/runs/19315010303/job/55244272668?pr=4505#step:4:4019

The key-value set when we attempt to verify a proposal on top of the same root is different:

https://github.com/ava-labs/avalanchego/actions/runs/19315010303/job/55244272668?pr=4505#step:4:4027

The same appears to be true for the success case.

The first attempt to propose on the parent root here:

https://github.com/ava-labs/avalanchego/actions/runs/19315010303/job/55244272679?pr=4505#step:4:4113

The second (where I assume we are verifying the root and need to look deeper to check this assumption):

https://github.com/ava-labs/avalanchego/actions/runs/19315010303/job/55244272679?pr=4505#step:4:4122

[aaronbuchwald]

Hmm this is interesting, it looks that within an individual run there is proposal 1 and then proposal 2 (we verify the root on the second due to the call pattern in the firewood wrapper). Proposal 1 and 2 within a single run are different, which may be perfectly valid and I need to look into what the two proposals are.

The key-value set included in proposal 1 is identical across success and failure and the key-value set included in proposal 2 is identical across success and failure as well.

This would indicate that when attempting to pass the same key-value set into firewood it calculates a different hash.

Interestingly, the success case invokes calling propose from database root (https://github.com/ava-labs/avalanchego/actions/runs/19315010303/job/55244272679?pr=4505#step:4:4122) indicating that the prior proposal has been fully committed to the DB and we are creating a new proposal directly on top of it. In contrast, the failure case logs "Calling Propose from root proposal" (ref: https://github.com/ava-labs/coreth/blob/aae47cf78ebbbdc56741ca7243a3c4b591ccf3fb/triedb/firewood/database.go#L552), which indicates that the parent is still a proposal and we are attempting to create a proposal on top of a proposal while the parent is being committed to disk (due to the async acceptor queue).

From this most recent set of runs, all 4 passing runs exhibit the same pattern of proposing on top of the database root at that block.

[aaronbuchwald]

There seem to be two different paths where a set of kv pairs gets turned into a hash on top of a parent root. Those two paths include:

• use arrangeKeyValuePairs to transform a MergedNodeSet into slices of kv pairs https://github.com/ava-labs/coreth/blob/0a0195cecbda7b7c3abcac28ee3a6370e01878d2/triedb/firewood/database.go#L569
• track the ordered set of operations applied to an account trie and calculate the root within hash(): https://github.com/ava-labs/coreth/blob/0a0195cecbda7b7c3abcac28ee3a6370e01878d2/triedb/firewood/account_trie.go#L208

It seems that the node set is created from Commit within the AccountTrie and should take care of collapsing the ordered operations into the resulting diff that should be applied to the trie

Commit: https://github.com/ava-labs/coreth/blob/0a0195cecbda7b7c3abcac28ee3a6370e01878d2/triedb/firewood/account_trie.go#L229
AddNode: https://github.com/ava-labs/libevm/blob/1ec8741af98f3d2c05691328f3f9caf560985c63/trie/trienode/node.go#L93

[rkuris]

Observations:

I noticed we're calling "GetFromRoot" with an empty key, usually 3 times per block. I think this is due to a check to see if a particular revision is available. Not really a problem except this could be a small perf win.

Every single GetFromRoot call matches in the success and failure case, including each return value, with one exception: there is one fewer call to "GetFromRoot" with an empty key in the failure case.

The base hash for the proposal that has a different hash is the same

The failure case is doing propose-on-propose while the success case is not

The keys and values are not in the same order, but contain the same data

The returned hash from Propose is different, and happens on the first proposal (obviously, that's why we get the error)

Since the base hash is the same in both the success and failure cases (0xfe03e921924f1d799658837edd289ea1cc00937d10af0d795ac756f22e0c7cde), and the inserts are functionally the same, this implies the bug is indeed a firewood issue, as we should be producing the same hash based on these different data values.

Technical details on the key input differences, success order (let's call these keys 1 2 3 4)

  91 244 168 24 251 98 222 230 16 149 74 87 249 245 144 88 63 22 126 253 155 21 60 174 244 247 195 74 53 0 56 37 41 13 236 217 84 139 98 168 214 3 69 169 136 56 111 200 75 166 188 149 72 64 8 246 54 47 147 22 14 243 229 99
  113 100 87 16 37 27 113 147 135 149 97 95 99 247 188 242 127 213 170 79 251 174 183 172 225 108 189 28 118 164 30 66
  91 244 168 24 251 98 222 230 16 149 74 87 249 245 144 88 63 22 126 253 155 21 60 174 244 247 195 74 53 0 56 37
  242 43 180 110 223 49 175 133 89 56 190 250 168 112 237 61 134 164 173 147 169 236 247 198 60 234 168 13 174 169 172 77

failure order (same keys, just ordered 1 3 4 2)

  91 244 168 24 251 98 222 230 16 149 74 87 249 245 144 88 63 22 126 253 155 21 60 174 244 247 195 74 53 0 56 37 41 13 236 217 84 139 98 168 214 3 69 169 136 56 111 200 75 166 188 149 72 64 8 246 54 47 147 22 14 243 229 99
  91 244 168 24 251 98 222 230 16 149 74 87 249 245 144 88 63 22 126 253 155 21 60 174 244 247 195 74 53 0 56 37
  242 43 180 110 223 49 175 133 89 56 190 250 168 112 237 61 134 164 173 147 169 236 247 198 60 234 168 13 174 169 172 77
  113 100 87 16 37 27 113 147 135 149 97 95 99 247 188 242 127 213 170 79 251 174 183 172 225 108 189 28 118 164 30 66

Based on this, it does seem that firewood is computing the wrong hash, which could either be a failure when computing the hash, or a failure when reading the nodes to construct the changes. I'm going to guess the latter and audit the code that prepares a node for modification racing against the parent being committed (that is, reparenting).

[demosdemon]

confirming still unresolved as of v0.0.16. I was able to trigger the same issue on blocks 326 and 21109. I also added hash checking after reading every node from disk (#1516) and still reproduced the merkle root hash mismatch and not a new one from a bad read.

[demosdemon]

After disabling io-uring writes, I was still able to reproduce a hash mismatch (block 29830, previously reported).